I'm tring to troubleshoot a problem with sending data from a light forwarder to a splunk server. In this particular case, the clients are 2 Windows 2008 R2 boxes running the "Client access server" role for exchange 2010. The splunk server is a redhat linux 5 64 bit box. Both are running splunk 4.1.4.
I'm trying to harvest logs from 2 cas servers. I suppose for those who are familiar with exchange 2010, I'm trying to harvest the following logs:
C:\Program Files\Microsoft\Exchange Server\V14\Logging\AddressBook Service\AddressBook*
C:\Program Files\Microsoft\Exchange Server\V14\Logging\Imap4\IMAP4*
C:\Program Files\Microsoft\Exchange Server\V14\Logging\Pop3\POP3*
C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA*
C:\inetpub\logs\LogFiles\W3SVC1\u_ex*
I started off with the first 4 logs (address book, imap, pop3 and rca). Things looked to be ok, and I was seeing active data from both machines. I was adding them one at a time to verify that each log was being collected properly. When I added the last log, I noticed that I stopped receiving events from one of the two cas servers. When I left it last night, the first one wasn't reporting. I tried running the splunk add oneshot command, and that got data to show up, but of course that was manually. I left it alone, and this morning, I noticed that the 2nd cas server was the one reporting back.
I'm not sure where the problem may be, but I see two things on logs (one on the client and one on the server) that point to a problem. On the client, I see this in the splunkd.log file over and over:
08-15-2010 15:45:53.760 INFO TailingProcessor - Could not send data to output queue (parsingQueue), retrying...
08-15-2010 15:45:53.760 INFO TailingProcessor - ...continuing.
I don't really understand what that really means or what its trying to do. I'm not sure if the timing matches, but I also see this on the splunkd.log of the splunk server:
08-15-2010 15:50:24.234 WARN DateParserVerbose - Failed to parse timestamp for event.
Context="source::C:\inetpub\logs\LogFiles\W3SVC1\u_ex100108.log|host::cas1|exchangewebaccesslog|remoteport::14759" Text="#Software: Microsoft Internet Information Services 7.5..."
The value after "Text=" isn't always that, but it is never actual data. I figure that particular warning on the splunk server is because the top lines of each log file contain header info that it can't parse. However, I'm not sure if that's enough to stop it from receiving data. I"m guessing its not because it seemed to be working fine before I added the web log.
I took a guess that maybe I was sending too many events after I added the web logs, so I tried adding this to my outputs.conf file:
maxQueueSize=200000
However, that didn't seem to make a difference. The other thing is that after a few restarts of the splunk light forwarder, the web logs seemed to be showing up for both clients, but then I stopped receiving data for all the other logs that were already working. When I attempted to put the TrailingProcessor in debug mode, I saw this for a file:
08-15-2010 15:40:52.195 DEBUG TailingProcessor - ****
08-15-2010 15:40:52.195 DEBUG TailingProcessor - File state notification for path='C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA_20100728-1.LOG' (first time).
08-15-2010 15:40:52.195 DEBUG TailingProcessor - Item 'C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA_20100728-1.LOG' matches stanza: C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA*.
08-15-2010 15:40:52.195 DEBUG TailingProcessor - Storing config 'C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA*' for app ''.
08-15-2010 15:40:52.195 DEBUG TailingProcessor - Entry is associated with 1 configuration(s).
08-15-2010 15:40:52.195 DEBUG TailingProcessor - Will attempt to read file: C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA_20100728-1.LOG.
08-15-2010 15:40:52.336 DEBUG TailingProcessor - Got classified_sourcetype='exchangerpcclientaccesslog' and classified_charset='UTF-8'.
08-15-2010 15:40:52.336 DEBUG TailingProcessor - About to read data (Opening file: C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA_20100728-1.LOG).
08-15-2010 15:40:52.367 DEBUG TailingProcessor - Will doublecheck EOF (in 3000ms)..
I don't see anything wrong that would tell me that its a problem reading the file itself. Here are the relevant files:
inputs.conf on the client side:
[monitor://C:\Program Files\Microsoft\Exchange Server\V14\Logging\AddressBook Service\AddressBook*]
index=idx-exchangemaillogs
sourcetype=exchangeaddressbooklog
[monitor://C:\Program Files\Microsoft\Exchange Server\V14\Logging\Imap4\IMAP4*]
index=idx-exchangemaillogs
sourcetype=exchangeimap4log
[monitor://C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA*]
index=idx-exchangemaillogs
sourcetype=exchangerpcclientaccesslog
[monitor://C:\inetpub\logs\LogFiles\W3SVC1]
index=idx-exchangemaillogs
sourcetype=exchangewebaccesslog
props.conf on the server side:
[exchangepop3log]
SHOULD_LINEMERGE=false
KV_MODE = none
REPORT-exchangepop3extract = exchangepop3log_extractions
[exchangeaddressbooklog]
SHOULD_LINEMERGE=false
KV_MODE = none
REPORT-exchangeaddressbookextract = exchangeaddressbooklog_extractions
[exchangeimap4log]
SHOULD_LINEMERGE=false
KV_MODE = none
REPORT-exchangeimap4extract = exchangeimap4log_extractions
[exchangerpcclientaccesslog]
SHOULD_LINEMERGE=false
KV_MODE = none
REPORT-exchangerpcclientaccessextract = exchangerpcclientaccesslog_extractions
[exchangewebaccesslog]
SHOULD_LINEMERGE=false
KV_MODE = none
REPORT-exchangewebaccessextract = exchangewebaccesslog_extractions
transforms.conf on the server side:
[exchangepop3log_extractions]
DELIMS = ","
FIELDS = "date-time","session-id","sequence-number","local-endpoint","remote-endpoint","event","data","context"
[exchangeaddressbooklog_extractions]
DELIMS = ","
FIELDS = "date-time","session-id","seq-number","client-name","organization-info","client-ip","server-ip","protocol","operation","rpc-status","processing-time","operation-specific","failures","authentication"
[exchangeimap4log_extractions]
DELIMS = ","
FIELDS = "date-time","session-id","sequence-number","local-endpoint","remote-endpoint","event","data","context"
[exchangerpcclientaccesslog_extractions]
DELIMS = ","
FIELDS = "date-time","session-id","seq-number","client-name","organization-info","client-software","client-software-version","client-mode","client-ip","server-ip","protocol","operation","rpc-status","processing-time","operation-specific","failures"
[exchangewebaccesslog_extractions]
DELIMS = " "
FIELDS = "date","time","s-ip","cs-method","cs-uri-stem","cs-uri-query","s-port","cs-username","c-ip","cs-version","cs(User-Agent)","cs(Cookie)","cs(Referer)","cs-host","sc-status","sc-substatus","sc-win32-status","time-taken"
and...just for sake of completion....the first bit of the files in question:
C:\Program Files\Microsoft\Exchange Server\V14\Logging\AddressBook Service\AddressBook*
#Software: Microsoft Exchange
#Version: 14.00.0694.000
#Log-type: AddressBook Protocol Logs
#Date: 2010-08-15T00:00:00.477Z
#Fields: date-time,session-id,seq-number,client-name,organization-info,client-ip,server-ip,protocol,operation,rpc-status,processing-time,operation-specific,failures,authentication
....data goes here....
C:\Program Files\Microsoft\Exchange Server\V14\Logging\Imap4\IMAP4*
#Software: Microsoft Exchange Server
#Version: 14.0.0.0
#Log-type: IMAP4 Protocol Log
#Date: 2010-08-15T19:44:10.128Z
#Fields: date-time,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context
C:\Program Files\Microsoft\Exchange Server\V14\Logging\Pop3\POP3*
#Software: Microsoft Exchange Server
#Version: 14.0.0.0
#Log-type: POP3 Protocol Log
#Date: 2010-08-15T16:26:19.597Z
#Fields: date-time,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context
C:\Program Files\Microsoft\Exchange Server\V14\Logging\RPC Client Access\RCA*
#Software: Microsoft Exchange
#Version: 14.00.0694.000
#Log-type: RCA Protocol Logs
#Date: 2010-08-15T00:00:30.087Z
#Fields: date-time,session-id,seq-number,client-name,organization-info,client-software,client-software-version,client-mode,client-ip,server-ip,protocol,operation,rpc-status,processing-time,operation-specific,failures
C:\inetpub\logs\LogFiles\W3SVC1\u_ex*
#Software: Microsoft Internet Information Services 7.5
#Version: 1.0
#Date: 2010-08-15 00:00:00
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs-version cs(User-Agent) cs(Cookie) cs(Referer) cs-host sc-status sc-substatus sc-win32-status time-taken
Unless I'm missing something obvious in my config files, can anyone point me in the right direction as to what would be causing the "C:\inetpub\logs\LogFiles\W3SVC1\u_ex*" to be showing up in my splunkd.log files on the light forwarder (as well as cause my data not to show up in splunk either!)
... View more