After upgrading Splunk App for Microsoft Exchange to 3.1.1, why am I getting "KV Store initialization has failed."?

[bravon]

After upgrading to the latest Splunk App for Microsoft Exchange (Version 3.1.1) I have the following problem with the new kvstore function.
The initial setup-wizard appeared to complete successfully, but then we noticed that this error:

"Could not create search. Error in 'inputlookup' command: The lookup table 'External command based lookup 'hostInformation' is not available because KV Store initialization has failed. Please contact your system administrator.' is invalid."

If i try to "Migrate lookups to KVStore":

Encountered error while migrating. Attempt to lookup migration status failed with error: "503 (Service Unavailable): KV Store initialization failed. Please contact your system administrator."

If i try to "Build lookups":

Building lookup - Lookup - Database Information ...
Lookup - Database Information built. (took 0.53s)
Lookup - Database Information could not be built.
Building lookup - Lookup - Performance Counters ...
Building lookup - Lookup - Host Information ...
Lookup - Host Information built. (took 0.59s)
Lookup - Host Information could not be built.
Lookup - Performance Counters built. (took 0.48s)
Lookup - Performance Counters could not be built.
Building lookup - WinApp_Lookup_Build_Perfmon - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Perfmon - Update - Server ...
Building lookup - WinApp_Lookup_Build_Event - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Event - Update - Server ...
WinApp_Lookup_Build_Event - Update - Server built. (took 0.55s)
WinApp_Lookup_Build_Event - Update - Server could not be built.
WinApp_Lookup_Build_Perfmon - Update - Detail built. (took 0.67s)
WinApp_Lookup_Build_Perfmon - Update - Detail could not be built.
WinApp_Lookup_Build_Perfmon - Update - Server built. (took 0.64s)
WinApp_Lookup_Build_Perfmon - Update - Server could not be built.
WinApp_Lookup_Build_Event - Update - Detail built. (took 0.56s)
WinApp_Lookup_Build_Event - Update - Detail could not be built.
Building lookup - WinApp_Lookup_Build_Hostmon - Update - Server ...
Building lookup - WinApp_Lookup_Build_Hostmon_Machine - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Hostmon_Services - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Hostmon_Process - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Hostmon_FS - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Netmon - Update - Detail ...
Building lookup - WinApp_Lookup_Build_Netmon - Update - Server ...
Building lookup - WinApp_Lookup_Build_Printmon - Update ...
WinApp_Lookup_Build_Hostmon_Process - Update - Detail built. (took 0.67s)
WinApp_Lookup_Build_Hostmon_Process - Update - Detail could not be built.
WinApp_Lookup_Build_Hostmon_FS - Update - Detail built. (took 0.75s)
WinApp_Lookup_Build_Hostmon_FS - Update - Detail could not be built.
WinApp_Lookup_Build_Printmon - Update built. (took 0.67s)
WinApp_Lookup_Build_Printmon - Update could not be built.
WinApp_Lookup_Build_Netmon - Update - Detail built. (took 0.61s)
WinApp_Lookup_Build_Netmon - Update - Detail could not be built.
WinApp_Lookup_Build_Hostmon - Update - Server built. (took 0.64s)
WinApp_Lookup_Build_Hostmon - Update - Server could not be built.
WinApp_Lookup_Build_Hostmon_Services - Update - Detail built. (took 0.66s)
WinApp_Lookup_Build_Hostmon_Services - Update - Detail could not be built.
WinApp_Lookup_Build_Netmon - Update - Server built. (took 0.58s)
WinApp_Lookup_Build_Netmon - Update - Server could not be built.
Building lookup - SiteInfo_Lookup_Update ...
Building lookup - ActiveDirectory: Update GPO Lookup ...
Building lookup - DomainSelector_Lookup ...
Building lookup - tSessions_Lookup_Update ...
Building lookup - HostToDomain_Lookup_Update ...
Building lookup - tHostInfo_Lookup_Update ...
Building lookup - ActiveDirectory: Update Group Lookup ...
Building lookup - ActiveDirectory: Update User Lookup ...
Building lookup - ActiveDirectory: Update Computer Lookup ...
SiteInfo_Lookup_Update built. (took 0.56s)
SiteInfo_Lookup_Update could not be built.
ActiveDirectory: Update GPO Lookup built. (took 0.45s)
ActiveDirectory: Update GPO Lookup could not be built.
HostToDomain_Lookup_Update built. (took 0.73s)
HostToDomain_Lookup_Update could not be built.
ActiveDirectory: Update Computer Lookup built. (took 0.64s)
ActiveDirectory: Update Computer Lookup could not be built.
ActiveDirectory: Update User Lookup built. (took 0.69s)
ActiveDirectory: Update User Lookup could not be built.
DomainSelector_Lookup built. (took 0.80s)
DomainSelector_Lookup could not be built.
ActiveDirectory: Update Group Lookup built. (took 0.69s)
ActiveDirectory: Update Group Lookup could not be built.
tSessions_Lookup_Update built. (took 0.70s)
tSessions_Lookup_Update could not be built.
tHostInfo_Lookup_Update built. (took 0.72s)
tHostInfo_Lookup_Update could not be built.
WinApp_Lookup_Build_Hostmon_Machine - Update - Detail built. (took 12.23s)
WinApp_Lookup_Build_Hostmon_Machine - Update - Detail could not be built.

The /services/server/introspection/kvstore/serverstatus on the SH show:

In handler 'kvstore-serverstatus': failed to get introspection data

mongod.exe isnt running on the SH. I tried restarting splunk / the server but it doesn't start up with splunk.

When I manually run "mongod.exe" on the SH (Windows 2012 R2):

D:\Splunk\bin>mongod --dbpath=D:\Splunk\var\lib\splunk/kvstore\mongo --port=8191 --timeStampFormat=iso8601-utc --smallfiles --oplogSize=1000
2015-02-09T18:46:28.242Z [initandlisten] MongoDB starting : pid=3648 port=8191 dbpath=D:\Splunk\var\lib\splunk/kvstore\m
ongo 64-bit host=SEARCHHEAD_NAME
2015-02-09T18:46:28.242Z [initandlisten]
2015-02-09T18:46:28.242Z [initandlisten] ** WARNING: You are running on a NUMA machine.
2015-02-09T18:46:28.242Z [initandlisten] **          We suggest disabling NUMA in the machine BIOS
2015-02-09T18:46:28.242Z [initandlisten] **          by enabling interleaving to avoid performance problems.
2015-02-09T18:46:28.242Z [initandlisten] **          See your BIOS documentation for more information.
2015-02-09T18:46:28.242Z [initandlisten]
2015-02-09T18:46:28.242Z [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2015-02-09T18:46:28.242Z [initandlisten] db version v2.6.4-splunk
2015-02-09T18:46:28.242Z [initandlisten] git version: beb52e78e1f3293130e7c4c7538bae49db11ecd9
2015-02-09T18:46:28.242Z [initandlisten] OpenSSL version: OpenSSL 1.0.1j-fips 15 Oct 2014
2015-02-09T18:46:28.242Z [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platfor
m=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49
2015-02-09T18:46:28.242Z [initandlisten] allocator: system
2015-02-09T18:46:28.242Z [initandlisten] options: { net: { port: 8191 }, replication: { oplogSizeMB: 1000 }, storage: {
dbPath: "D:\Splunk\var\lib\splunk/kvstore\mongo", smallFiles: true }, systemLog: { timeStampFormat: "iso8601-utc" } }
2015-02-09T18:46:28.258Z [initandlisten] journal dir=D:\Splunk\var\lib\splunk/kvstore\mongo\journal
2015-02-09T18:46:28.258Z [initandlisten] recover : no journal files present, no recovery needed
2015-02-09T18:46:28.383Z [initandlisten] waiting for connections on port 8191

Could someone point me in the right direction? 🙂

[bravon · Accepted solution]

@dgladkikh_splunk
I ran ProcMon while restarting splunk and found out that I had this one ACCESS DENIED entry:

Edit: I should point out that this problem has been around for 7 days - So even tho there is a new modify-date on the file this problem existed before that date.
The path is D:\Splunk\var\lib\splunk\kvstore\mongo\s_splunk74nHmRcOKKKd57KUS+JhiJYM_Exch*****.0
I was checking permissions on the \journal\ folder/files

So I looked - and surely only MY user has permissions on that file. All the other files have the correct permissions.
Im not saying its impossible, but Im pretty sure I havnt touched the file.

After fixing the permissions and restarting splunk the mongod.exe process starts up with Splunk and everything seems to be working.

[bravon]

I have read both posts.

The first post talks about a "Service".
I can't find any service called "mongod" (Maybe this is the problem? This should be a Windows Service listed under services.msc?)

The 2nd post solves the problem by "I deleted the mongod.lock file from C:Program FilesSplunkvarlibsplunkkvstoremongo and restarted my Splunk instance, and now things are working as expected. " and that solution doesn`t work for me.

Edit:

This is from "mongod" logfile:

 2015-02-09T19:27:03.301Z [initandlisten] journal dir=D:\Splunk\var\lib\splunk/kvstore\mongo\journal
 2015-02-09T19:27:03.301Z [initandlisten] recover begin
 2015-02-09T19:27:03.301Z [initandlisten] info no lsn file in journal/ directory
 2015-02-09T19:27:03.301Z [initandlisten] recover lsn: 0
 2015-02-09T19:27:03.301Z [initandlisten] recover D:\Splunk\var\lib\splunk/kvstore\mongo\journal\j._0
 2015-02-09T19:27:03.301Z [initandlisten] CreateFileW for D:\Splunk\var\lib\splunk/kvstore\mongo\journal\j._0 failed with errno:5 Access is denied. (file size is 16384) in MemoryMappedFile::map
 2015-02-09T19:27:03.301Z [initandlisten] Assertion: 13544:recover error couldn't open D:\Splunk\var\lib\splunk/kvstore\mongo\journal\j._0
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x702353
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x6a97df
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x695a29
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x695933
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x2175dc
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x2167e8
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x214463
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x2183c3
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0x20592e
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0xabea27
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0xac0267
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0xac0f02
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0xac2e25
 2015-02-09T19:27:03.426Z [initandlisten] mongod.exe      mongo::parseNumberFromStringWithBase<unsigned __int64>+0xaff4f0
 2015-02-09T19:27:03.426Z [initandlisten] KERNEL32.DLL    BaseThreadInitThunk+0x22
 2015-02-09T19:27:03.426Z [initandlisten] 
 2015-02-09T19:27:03.457Z [initandlisten] dbexception during recovery: 13544 recover error couldn't open D:\Splunk\var\lib\splunk/kvstore\mongo\journal\j._0
 2015-02-09T19:27:03.457Z [initandlisten] exception in initAndListen: 13544 recover error couldn't open D:\Splunk\var\lib\splunk/kvstore\mongo\journal\j._0, terminating
 2015-02-09T19:27:03.457Z [initandlisten] dbexit: 
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: going to close listening sockets...
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: going to flush diaglog...
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: going to close sockets...
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: waiting for fs preallocator...
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: lock for final commit...
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: final commit...
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: closing all files...
 2015-02-09T19:27:03.457Z [initandlisten] closeAllFiles() finished
 2015-02-09T19:27:03.457Z [initandlisten] shutdown: removing fs lock...
 2015-02-09T19:27:03.457Z [initandlisten] dbexit: really exiting now

[dgladkikh_splun]

Could you check if there are any other mongod processes on your machine are running?
Also could you verify what is the ownership of directory/files under this path D:\Splunk\var\lib\splunk/kvstore\mongo\journal\? Is it the same user as you run your splunk instance?

[bravon]

There are no other mongod-processes.
Splunkd is running as Local System
Journal folder has system account listed with "full control", owner is "Administrators", "effective permissions check" ok.

[damode]

Hi Bravon,

If you found the solution to this issue, please share it. I am facing the same issue.

Thanks,
Dev

[ChrisG]

There are two previous postings that seem to indicate you can fix the problem by restarting the mongod service manually:

• http://answers.splunk.com/answers/208349/why-am-i-getting-kv-store-error-external-command-b.html
• http://answers.splunk.com/answers/206030/splunk-app-for-windows-infrastructure-why-am-i-get-1.html