Splunk internal logs: alerting

Here is what you will find if you go looking in Splunk’s internal logs when a scheduled search fires an alert. These actions don’t necessarily happen in exactly this order, but this is typically how I would go about finding evidence of them in the logs.

A regular saved search with an email alert

This is the alert in the savedsearches.conf

[alert1]
action.email = 1
action.email.inline = 1
action.email.to = feorlen@feorlens-MacBook.local
alert.suppress = 0
alert.track = 1
cron_schedule = */5 * * * *
enableSched = 1
search = * | head 3

splunkd_access.log

The search ran as user “admin” and now it tells splunkd to execute the actions. The sendemail search command gets the configuration (note it does it as splunk-system-user) and then requests any messages from the search job to include.

127.0.0.1 - admin [06/Sep/2012:14:35:00.602 -0700] "POST /servicesNS/admin/search/saved/searches/alert1/notify?trigger.condition_state=1 HTTP/1.0" 200 256 - - - 4ms
127.0.0.1 - splunk-system-user [06/Sep/2012:14:35:01.021 -0700] "GET /servicesNS/nobody/search/admin/alert_actions/email HTTP/1.1" 200 5913 - - - 3ms
127.0.0.1 - splunk-system-user [06/Sep/2012:14:35:01.030 -0700] "GET /services/search/jobs/scheduler__admin__search__alert1_at_1346967300_cccba25f4f1da408?message_level=warn HTTP/1.1" 200 11766 - - - 6ms

scheduler.log

SavedSplunker identifies the alert action to execute

09-06-2012 14:35:06.211 -0700 INFO  SavedSplunker - savedsearch_id="admin;search;alert1", user="admin", app="search", savedsearch_name="alert1", status=success, digest_mode=1, scheduled_time=1346967300, dispatch_time=1346967300, run_time=0.149, result_count=3, alert_actions="email", sid="scheduler__admin__search__alert1_at_1346967300_cccba25f4f1da408", suppressed=0, thread_id="AlertNotifierWorker-0"

The dispatch directory holds the search artifacts for this particular search

# pwd
/Applications/splunk/var/run/splunk/dispatch
# ls scheduler__admin__search__alert1_at_1346967300_cccba25f4f1da408
args.txt	buckets	 info.csv  peers.csv  results.csv.gz  status.csv  audited  events  metadata.csv  request.csv  search.log

search.log

Many details of the search, like what we actually asked for.
ct, et and lt are current time and earliest and latest time requested

09-06-2012 14:35:00.539 INFO  SearchParser - PARSING: litsearch * | fields  keepcolorder=t "host" "index" "linecount" "source" "sourcetype" "splunk_server" | prehead  limit=3 null=false keeplast=false
09-06-2012 14:35:00.570 INFO  IndexScopedSearch - LISPY for index=main is lispy='[ AND ]' ct=1346967300 et=0 lt=1346967300 dbsize=8

python.log

The email alerting script, sendemail.py, constructs the email and sends it, logging the status. If the email server returned an error, that would also be here.

2012-09-06 14:35:06,191 INFO Sending email. subject="Splunk Alert: alert1", results_link="http://feorlens-MacBook.local:8000/app/search/@go?sid=scheduler__admin__search__alert1_at_1346967300_cccba25f4f1da408", recepients="['feorlen@feorlens-MacBook.local']"

Alert that triggers a script

This search runs the sample echo.sh script (which doesn’t do much, but yours could.)

[alert2]
action.email.inline = 1
action.script = 1
action.script.filename = echo.sh
alert.suppress = 0
alert.track = 1
cron_schedule = */5 * * * *
enableSched = 1
search = * | head 2

The request in splunkd_access.log

127.0.0.1 - admin [06/Sep/2012:15:05:01.709 -0700] "POST /servicesNS/admin/search/saved/searches/alert2/notify?trigger.condition_state=1 HTTP/1.0" 200 256 - - - 4ms

When it runs correctly, it is logged to python.log

2012-09-06 15:05:01,904 INFO ['/Applications/splunk/bin/scripts/echo.sh', '2', '* | head 2', '* | head 2', 'alert2', 'Saved Search [alert2] always(2)', 'http://feorlens-MacBook.local:8000/app/search/@go?sid=scheduler__admin__search__alert2_at_1346969100_1c6a243826cdb171', '', '/Applications/splunk/var/run/splunk/dispatch/scheduler__admin__search__alert2_at_1346969100_1c6a243826cdb171/results.csv.gz']
2012-09-06 15:05:01,993 INFO runshellscript: ['/bin/sh', '/Applications/splunk/bin/scripts/echo.sh', '2', '* | head 2', '* | head 2', 'alert2', 'Saved Search [alert2] always(2)', 'http://feorlens-MacBook.local:8000/app/search/@go?sid=scheduler__admin__search__alert2_at_1346969100_1c6a243826cdb171', '', '/Applications/splunk/var/run/splunk/dispatch/scheduler__admin__search__alert2_at_1346969100_1c6a243826cdb171/results.csv.gz']

Now with a script that doesn’t exist

[alert3]
action.email.inline = 1
action.script = 1
action.script.filename = bogus.sh
alert.suppress = 0
alert.track = 1
cron_schedule = */5 * * * *
enableSched = 1
search = * | head 4

splunkd_access.log

127.0.0.1 - admin [06/Sep/2012:15:10:01.902 -0700] "POST /servicesNS/admin/search/saved/searches/alert3/notify?trigger.condition_state=1 HTTP/1.0" 200 256 - - - 4ms

splunkd couldn’t execute it, so the error goes to splunkd.log

09-06-2012 15:10:02.091 -0700 ERROR script - command="runshellscript", Cannot find script at /Applications/splunk/bin/scripts/bogus.sh