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

WiredTiger on Btrfs - failed to read 4096 bytes at offset 0: Input/output error

    • Type: Icon: Bug Bug
    • Resolution: Incomplete
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.2.6, 3.2.8, 3.2.11, 3.4.1
    • Component/s: WiredTiger
    • Labels:
    • Linux

      I'm running MongoDB 3.4.1 on our CI systems (CentOS 7.3) in a Btrfs subvolume. Every now and then (2-4 weeks) the following error leaves the database in a non-repairable state. There are no messages in syslog/dmesg showing any fs errors during this time.

      2017-01-31T16:38:01.118+0000 E STORAGE  [conn9] WiredTiger error (5) [1485880681:118369][63127:0x7ff17bbe1700], file:index-5-8173061028522095950.wt, WT_SESSION.open_cursor: /opt/mongo/db/index-5-81730610285220
      95950.wt: handle-read: pread: failed to read 4096 bytes at offset 0: Input/output error
      2017-01-31T16:38:01.118+0000 I -        [conn9] Invariant failure: ret resulted in status UnknownError: 5: Input/output error at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 95
      2017-01-31T16:38:01.118+0000 I -        [conn9]
      
      ***aborting after invariant() failure
      
      
      2017-01-31T16:38:01.137+0000 F -        [conn9] Got signal: 6 (Aborted).
      
       0x7ff188124351 0x7ff188123449 0x7ff18812392d 0x7ff1857fa370 0x7ff18545f1d7 0x7ff1854608c8 0x7ff1873b887f 0x7ff187e37766 0x7ff187e3547c 0x7ff187e0fd57 0x7ff1878112c8 0x7ff187744048 0x7ff18774456f 0x7ff187754cb
      3 0x7ff18773305e 0x7ff187754cb3 0x7ff187748d26 0x7ff187754cb3 0x7ff187a580ca 0x7ff187a589eb 0x7ff18763face 0x7ff187616847 0x7ff187617be0 0x7ff187c2e54d 0x7ff1878348f2 0x7ff1878368f6 0x7ff187426f1d 0x7ff1874278
      5d 0x7ff188089822 0x7ff1857f2dc5 0x7ff18552173d
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"7FF186BA5000","o":"157F351","s":"_ZN5mongo15printStackTraceERSo"},{"b":"7FF186BA5000","o":"157E449"},{"b":"7FF186BA5000","o":"157E92D"},{"b":"7FF1857EB000","o":"F370"},{"b":"7FF18542A000","
      o":"351D7","s":"gsignal"},{"b":"7FF18542A000","o":"368C8","s":"abort"},{"b":"7FF186BA5000","o":"81387F","s":"_ZN5mongo25fassertFailedWithLocationEiPKcj"},{"b":"7FF186BA5000","o":"1292766","s":"_ZN5mongo17Wired
      TigerSession9getCursorERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmb"},{"b":"7FF186BA5000","o":"129047C","s":"_ZN5mongo16WiredTigerCursorC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmbPN
      S_16OperationContextE"},{"b":"7FF186BA5000","o":"126AD57","s":"_ZNK5mongo21WiredTigerIndexUnique9newCursorEPNS_16OperationContextEb"},{"b":"7FF186BA5000","o":"C6C2C8","s":"_ZNK5mongo17IndexAccessMethod9newCurs
      orEPNS_16OperationContextEb"},{"b":"7FF186BA5000","o":"B9F048","s":"_ZN5mongo9IndexScan13initIndexScanEv"},{"b":"7FF186BA5000","o":"B9F56F","s":"_ZN5mongo9IndexScan6doWorkEPm"},{"b":"7FF186BA5000","o":"BAFCB3"
      ,"s":"_ZN5mongo9PlanStage4workEPm"},{"b":"7FF186BA5000","o":"B8E05E","s":"_ZN5mongo10FetchStage6doWorkEPm"},{"b":"7FF186BA5000","o":"BAFCB3","s":"_ZN5mongo9PlanStage4workEPm"},{"b":"7FF186BA5000","o":"BA3D26",
      "s":"_ZN5mongo10LimitStage6doWorkEPm"},{"b":"7FF186BA5000","o":"BAFCB3","s":"_ZN5mongo9PlanStage4workEPm"},{"b":"7FF186BA5000","o":"EB30CA","s":"_ZN5mongo12PlanExecutor11getNextImplEPNS_11SnapshottedINS_7BSONO
      bjEEEPNS_8RecordIdE"},{"b":"7FF186BA5000","o":"EB39EB","s":"_ZN5mongo12PlanExecutor7getNextEPNS_7BSONObjEPNS_8RecordIdE"},{"b":"7FF186BA5000","o":"A9AACE","s":"_ZN5mongo7FindCmd3runEPNS_16OperationContextERKNS
      t7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERNS_7BSONObjEiRS8_RNS_14BSONObjBuilderE"},{"b":"7FF186BA5000","o":"A71847","s":"_ZN5mongo7Command3runEPNS_16OperationContextERKNS_3rpc16RequestInterfaceEPNS3_2
      1ReplyBuilderInterfaceE"},{"b":"7FF186BA5000","o":"A72BE0","s":"_ZN5mongo7Command11execCommandEPNS_16OperationContextEPS0_RKNS_3rpc16RequestInterfaceEPNS4_21ReplyBuilderInterfaceE"},{"b":"7FF186BA5000","o":"10
      8954D","s":"_ZN5mongo11runCommandsEPNS_16OperationContextERKNS_3rpc16RequestInterfaceEPNS2_21ReplyBuilderInterfaceE"},{"b":"7FF186BA5000","o":"C8F8F2"},{"b":"7FF186BA5000","o":"C918F6","s":"_ZN5mongo16assemble
      ResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE"},{"b":"7FF186BA5000","o":"881F1D","s":"_ZN5mongo23ServiceEntryPointMongod12_sessionLoopERKSt10shared_ptrINS_9transport7Session
      EE"},{"b":"7FF186BA5000","o":"88285D"},{"b":"7FF186BA5000","o":"14E4822"},{"b":"7FF1857EB000","o":"7DC5"},{"b":"7FF18542A000","o":"F773D","s":"clone"}],"processInfo":{ "mongodbVersion" : "3.4.1", "gitVersion"
      : "5e103c4f5583e2566a45d740225dc250baacfbd7", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "3.10.0-327.18.2.el7.x86_64", "version" : "#1 SMP Thu May 12 11:03:55 UTC 2016", "machine" : "
      x86_64" }, "somap" : [ { "b" : "7FF186BA5000", "elfType" : 3, "buildId" : "1CFAD184A19D237BE2A54C39E15942B7F1E1F618" }, { "b" : "7FFCB2666000", "elfType" : 3, "buildId" : "627B075D566CF4BFF68497DAB7DF9B024F8E5
      A83" }, { "b" : "7FF186715000", "path" : "/lib64/libssl.so.10", "elfType" : 3, "buildId" : "D0018CA5E24522ED0DC1844556FA8DBC4B39D5C3" }, { "b" : "7FF18632B000", "path" : "/lib64/libcrypto.so.10", "elfType" : 3
      , "buildId" : "8756D2315BF50F8610875B1AFF128198FB9D202D" }, { "b" : "7FF186123000", "path" : "/lib64/librt.so.1", "elfType" : 3, "buildId" : "82E77ADE22BC9FFF8D3458BD37331E7EDF174C28" }, { "b" : "7FF185F1F000"
      , "path" : "/lib64/libdl.so.2", "elfType" : 3, "buildId" : "C5F560504E1AF52E29679C3B52FF11121015D6BB" }, { "b" : "7FF185C1D000", "path" : "/lib64/libm.so.6", "elfType" : 3, "buildId" : "721C7CC9488EFA25F83B48A
      F713AB27DBE48EF3E" }, { "b" : "7FF185A07000", "path" : "/lib64/libgcc_s.so.1", "elfType" : 3, "buildId" : "408B46E291B2D4C9612E27C0509D165D7E186D40" }, { "b" : "7FF1857EB000", "path" : "/lib64/libpthread.so.0"
      , "elfType" : 3, "buildId" : "C3DEB1FA27CD0C1C3CC575B944ABACBA0698B0F2" }, { "b" : "7FF18542A000", "path" : "/lib64/libc.so.6", "elfType" : 3, "buildId" : "8B2C421716985B927AA0CAF2A05D0B1F452367F7" }, { "b" :
      "7FF186983000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "8F3E366E2DB73C330A3791DEAE31AE9579099B44" }, { "b" : "7FF1851DC000", "path" : "/lib64/libgssapi_krb5.so.2", "elfType" : 3, "buildId" : "A2499C359AA179EE23324ED949C0E508E4434F10" }, { "b" : "7FF184EF5000", "path" : "/lib64/libkrb5.so.3", "elfType" : 3, "buildId" : "E09A34D9083DC6FEAF7018C09D55631DEEE2836D" }, { "b" : "7FF184CF1000", "path" : "/lib64/libcom_err.so.2", "elfType" : 3, "buildId" : "BF54B7C8932E450769FBBB8B18864D1DD70BBC67" }, { "b" : "7FF184ABF000", "path" : "/lib64/libk5crypto.so.3", "elfType" : 3, "buildId" : "BF8F00D7CB849ADB0B7A4703BC7B8D66AEE6A49C" }, { "b" : "7FF1848A9000", "path" : "/lib64/libz.so.1", "elfType" : 3, "buildId" : "EA8E45DC8E395CC5E26890470112D97A1F1E0B65" }, { "b" : "7FF18469A000", "path" : "/lib64/libkrb5support.so.0", "elfType" : 3, "buildId" : "1E7A92FDD6FB3871DA97F4BCA2E147E72B6B6E1F" }, { "b" : "7FF184496000", "path" : "/lib64/libkeyutils.so.1", "elfType" : 3, "buildId" : "2E01D5AC08C1280D013AAB96B292AC58BC30A263" }, { "b" : "7FF18427C000", "path" : "/lib64/libresolv.so.2", "elfType" : 3, "buildId" : "FE7AE845A123A3DFC0FDC2408BCBC2BA8B61B158" }, { "b" : "7FF184055000", "path" : "/lib64/libselinux.so.1", "elfType" : 3, "buildId" : "76687CA31A406854DF3BCF8D03055656F56E6892" }, { "b" : "7FF183DF4000", "path" : "/lib64/libpcre.so.1", "elfType" : 3, "buildId" : "AE64AA461A26E01F60408013D361749D56DD0AE1" } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x41) [0x7ff188124351]
       mongod(+0x157E449) [0x7ff188123449]
       mongod(+0x157E92D) [0x7ff18812392d]
       libpthread.so.0(+0xF370) [0x7ff1857fa370]
       libc.so.6(gsignal+0x37) [0x7ff18545f1d7]
       libc.so.6(abort+0x148) [0x7ff1854608c8]
       mongod(_ZN5mongo25fassertFailedWithLocationEiPKcj+0x0) [0x7ff1873b887f]
       mongod(_ZN5mongo17WiredTigerSession9getCursorERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmb+0x106) [0x7ff187e37766]
       mongod(_ZN5mongo16WiredTigerCursorC1ERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEmbPNS_16OperationContextE+0x4C) [0x7ff187e3547c]
       mongod(_ZNK5mongo21WiredTigerIndexUnique9newCursorEPNS_16OperationContextEb+0x157) [0x7ff187e0fd57]
       mongod(_ZNK5mongo17IndexAccessMethod9newCursorEPNS_16OperationContextEb+0x28) [0x7ff1878112c8]
       mongod(_ZN5mongo9IndexScan13initIndexScanEv+0x58) [0x7ff187744048]
       mongod(_ZN5mongo9IndexScan6doWorkEPm+0x14F) [0x7ff18774456f]
       mongod(_ZN5mongo9PlanStage4workEPm+0x63) [0x7ff187754cb3]
       mongod(_ZN5mongo10FetchStage6doWorkEPm+0x29E) [0x7ff18773305e]
       mongod(_ZN5mongo9PlanStage4workEPm+0x63) [0x7ff187754cb3]
       mongod(_ZN5mongo10LimitStage6doWorkEPm+0x76) [0x7ff187748d26]
       mongod(_ZN5mongo9PlanStage4workEPm+0x63) [0x7ff187754cb3]
       mongod(_ZN5mongo12PlanExecutor11getNextImplEPNS_11SnapshottedINS_7BSONObjEEEPNS_8RecordIdE+0x19A) [0x7ff187a580ca]
       mongod(_ZN5mongo12PlanExecutor7getNextEPNS_7BSONObjEPNS_8RecordIdE+0x4B) [0x7ff187a589eb]
       mongod(_ZN5mongo7FindCmd3runEPNS_16OperationContextERKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEERNS_7BSONObjEiRS8_RNS_14BSONObjBuilderE+0x104E) [0x7ff18763face]
       mongod(_ZN5mongo7Command3runEPNS_16OperationContextERKNS_3rpc16RequestInterfaceEPNS3_21ReplyBuilderInterfaceE+0x527) [0x7ff187616847]
       mongod(_ZN5mongo7Command11execCommandEPNS_16OperationContextEPS0_RKNS_3rpc16RequestInterfaceEPNS4_21ReplyBuilderInterfaceE+0x9E0) [0x7ff187617be0]
       mongod(_ZN5mongo11runCommandsEPNS_16OperationContextERKNS_3rpc16RequestInterfaceEPNS2_21ReplyBuilderInterfaceE+0x26D) [0x7ff187c2e54d]
       mongod(+0xC8F8F2) [0x7ff1878348f2]
       mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x766) [0x7ff1878368f6]
       mongod(_ZN5mongo23ServiceEntryPointMongod12_sessionLoopERKSt10shared_ptrINS_9transport7SessionEE+0x1ED) [0x7ff187426f1d]
       mongod(+0x88285D) [0x7ff18742785d]
       mongod(+0x14E4822) [0x7ff188089822]
       libpthread.so.0(+0x7DC5) [0x7ff1857f2dc5]
       libc.so.6(clone+0x6D) [0x7ff18552173d]
      

      When we try to restart it affects other files (too?).

      2017-02-01T17:31:51.215+0000 I CONTROL  [main] ***** SERVER RESTARTED *****
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] MongoDB starting : pid=21524 port=27017 dbpath=/opt/mongo/db 64-bit host=outmatch-dev
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] db version v3.4.1
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] git version: 5e103c4f5583e2566a45d740225dc250baacfbd7
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] allocator: tcmalloc
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] modules: none
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] build environment:
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten]     distmod: rhel70
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten]     distarch: x86_64
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten]     target_arch: x86_64
      2017-02-01T17:31:51.222+0000 I CONTROL  [initandlisten] options: { config: "/opt/mongo/conf/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, processManagement: { fork: false, pidFilePath: "/var/run/mongod/mongod.pid" }, security: { authorization: "enabled" }, storage: { dbPath: "/opt/mongo/db", engine: "wiredTiger", wiredTiger: { collectionConfig: { blockCompressor: "zlib" } } }, systemLog: { destination: "file", logAppend: true, path: "/opt/mongo/log/mongod.log" } }
      2017-02-01T17:31:51.222+0000 W -        [initandlisten] Detected unclean shutdown - /opt/mongo/db/mongod.lock is not empty.
      2017-02-01T17:31:51.271+0000 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
      2017-02-01T17:31:51.271+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3476M,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
      2017-02-01T17:31:51.305+0000 E STORAGE  [initandlisten] WiredTiger error (5) [1485970311:305130][21524:0x7fc41fde8dc0], file:WiredTiger.wt, connection: /opt/mongo/db/WiredTiger.wt: handle-read: pread: failed to read 4096 bytes at offset 0: Input/output error
      2017-02-01T17:31:51.306+0000 I -        [initandlisten] Assertion: 28595:5: Input/output error src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp 267
      2017-02-01T17:31:51.311+0000 I STORAGE  [initandlisten] exception in initAndListen: 28595 5: Input/output error, terminating
      2017-02-01T17:31:51.311+0000 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
      2017-02-01T17:31:51.311+0000 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27017.sock
      2017-02-01T17:31:51.311+0000 I NETWORK  [initandlisten] shutdown: going to flush diaglog...
      2017-02-01T17:31:51.311+0000 I CONTROL  [initandlisten] now exiting
      2017-02-01T17:31:51.311+0000 I CONTROL  [initandlisten] shutting down with code:100
      

            Assignee:
            mark.agarunov Mark Agarunov
            Reporter:
            mgoehler Michael Göhler
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: