A Boy and His Logs

A boy and his logs
John E. Vincent
(@lusis)
DevOpsATL
7/11/12

View Slide

Let me tell you a story about
a boy....

View Slide

View Slide

He's got logs over here..

View Slide

Huge logs...

View Slide

Can't make any sense of them...

View Slide

(Probably came from a Node app)

View Slide

There's a lot of data in these logs

View Slide

He just wants to get the over here

View Slide

Maybe analyze them?

View Slide

It's cool, man..

View Slide

Logstash makes logging sexy

View Slide

Have a seat over here and I'll tell you
how.

View Slide

What is Logstash?

View Slide

Let's answer a different
question first...

View Slide

What are logs?

View Slide

Jul 11 09:07:37 jvstratusmbp login[23211]: in pam_sm_acct_mgmt():
OpenDirectory - Membership cache TTL set to 1800.
Jul 11 09:07:37 jvstratusmbp login[23211]: in od_record_check_pwpolicy():
retval: 0
Jul 11 09:07:37 jvstratusmbp login[23211]: in
od_record_attribute_create_cfstring(): returned 2 attributes for
dsAttrTypeStandard:AuthenticationAuthority
retval: 0
retval: 0
retval: 0

View Slide

com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException:
Column 'machine_image' cannot be null
at sun.reflect.GeneratedConstructorAccessor491.newInstance(Unknown
Source)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstruc
torAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:406)
at com.mysql.jdbc.Util.getInstance(Util.java:381)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3558)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3490)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2109)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2648)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2077
)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2362)
at
at
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(Delegating
PreparedStatement.java:105)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(Delegating
PreparedStatement.java:105)

View Slide

[11 Jul 2012 00:08:42.066] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT
`region`.àccount`, `region`.àctive`, `region`.`keypair`, `region`.`provider_region`,
`region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.àccount`
= ? ORDER BY `region`.`provider_region_id`
`provider_rdbms`.àdmin_user`, `provider_rdbms`.`cloud_id`,
`provider_rdbms`.`creation_timestamp`, `provider_rdbms`.`current_state`,
`provider_rdbms`.`database_engine`, `provider_rdbms`.`description`,
`provider_rdbms`.`dns_name`, `provider_rdbms`.ènstratus_rdbms_id`, `provider_rdbms`.`ha`,
`provider_rdbms`.`host_port`, `provider_rdbms`.`maintenance_end_day`,
`provider_rdbms`.`maintenance_end_hour`, `provider_rdbms`.`maintenance_end_minute`,
`provider_rdbms`.`maintenance_start_day`, `provider_rdbms`.`maintenance_start_hour`,
`provider_rdbms`.`maintenance_start_minute`, `provider_rdbms`.`name`,
`provider_rdbms`.`product_size`, `provider_rdbms`.`provider_configuration_id`,
`provider_rdbms`.`provider_data_center_id`, `provider_rdbms`.`provider_owner_id`,
`provider_rdbms`.`provider_rdbms_id`, `provider_rdbms`.`provider_region_id`,
`provider_rdbms`.`recovery_point_timestamp`, `provider_rdbms`.`snapshot_end_day`,
`provider_rdbms`.`snapshot_end_hour`, `provider_rdbms`.`snapshot_end_minute`,
`provider_rdbms`.`snapshot_retention_in_days`, `provider_rdbms`.`snapshot_start_day`,
`provider_rdbms`.`snapshot_start_hour`, `provider_rdbms`.`snapshot_start_minute`,
`provider_rdbms`.`storage_in_gb` FROM `provider_rdbms` WHERE `provider_rdbms`.`cloud_id` = ?
AND `provider_rdbms`.`provider_owner_id` = ? AND `provider_rdbms`.`provider_region_id` = ?
AND `provider_rdbms`.`provider_rdbms_id` = ?

View Slide

Jul 11 06:24:27 localhost haproxy[953]: 127.0.0.1:47963 [11/Jul/2012:06:14:29.940] api-fe
api-be/api-c 0/0/0/597587/+597587 200 +181 - - ---- 9/9/9/5/0 0/0 {50.18.111.113} "GET
/api/enstratus/2012-02-29/infrastructure/Snapshot?regionId=7141&volumeId=118593 HTTP/1.1"
api-be/api-b 0/0/0/1954/+1954 204 +89 - - ---- 9/9/8/4/0 0/0 {50.18.111.113} "DELETE
/api/enstratus/2012-02-29/infrastructure/Snapshot/20908911 HTTP/1.1"
api-be/api-c 0/0/0/2389/+2389 204 +89 - - ---- 9/9/7/4/0 0/0 {50.18.111.113} "DELETE
api-be/api-c 0/0/0/1880/+1880 204 +89 - - ---- 9/9/6/3/0 0/0 {50.18.111.113} "DELETE
api-be/api-b 0/0/0/2000/+2000 204 +89 - - ---- 7/7/7/4/0 0/0 {50.18.111.113} "DELETE
api-be/api-b 0/0/0/-1/+600002 504 +194 - - sH-- 6/6/5/2/0 0/0 {50.18.111.113} "GET
api-be/api-c 0/0/0/-1/+600001 504 +194 - - sH-- 4/4/4/2/0 0/0 {50.18.111.113} "GET
api-be/api-b 0/0/0/-1/+600002 504 +194 - - sH-- 3/3/3/1/0 0/0 {50.18.111.113} "GET

View Slide

Jul 4 02:10:42 lb-api-a pound: api.enstratus.com 24.118.90.130 - - [04/Jul/2012:02:10:42
+0000] "GET / HTTP/1.1" 404 955 "" "Mozilla/5.0 (Macin
tosh; Intel Mac OS X 10_7_4) AppleWebKit/534.57.2 (KHTML, like Gecko) Version/5.1.7
Safari/534.57.2"
+0000] "GET /favicon.ico HTTP/1.1" 200 824 "https://ap
i.enstratus.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_7_4) AppleWebKit/534.57.2
(KHTML, like Gecko) Version/5.1.7 Safari/534.57.2"
+0000] "GET /ai HTTP/1.1" 404 961 "" "Mozilla/5.0 (Mac
intosh; Intel Mac OS X 10_7_4) AppleWebKit/534.57.2 (KHTML, like Gecko) Version/5.1.7
Safari/534.57.2"
+0000] "GET /api HTTP/1.1" 200 348 "" "Mozilla/5.0 (Ma
cintosh; Intel Mac OS X 10_7_4) AppleWebKit/534.57.2 (KHTML, like Gecko) Version/5.1.7
Safari/534.57.2"
Jul 4 02:14:20 lb-api-a pound: api.enstratus.com:443 216.27.162.123 - -
[04/Jul/2012:02:14:20 +0000] "GET /api/enstratus/2012-02-29/infrastruct
ure/Server HTTP/1.1" 200 458 "" "enstratus.rb"
Jul 4 02:14:21 lb-api-a pound: api.enstratus.com:443 216.27.162.123 - -
[04/Jul/2012:02:14:21 +0000] "GET /api/enstratus/2012-02-29/infrastruct
ure/Server HTTP/1.1" 200 458 "" "enstratus.rb"
+0000] "GET /api/enstratus/2012-02-29/infrastructure/
Server?activeOnly=false HTTP/1.1" 200 19933 "" "enstratus.rb"
+0000] "GET /api/enstratus/2012-02-29/infrastructure/
Server?activeOnly=false HTTP/1.1" 200 97563 "" "enstratus.rb"

View Slide

2012-07-11 03:33:50.746 [info] <0.202.0>@riak_core:wait_for_service:410 Wait complete for
service riak_pipe (0 seconds)
2012-07-11 03:33:50.746 [info] <0.376.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack:
16MB, max heap: 8MB, pool: riak_kv_js_map) host starting (<0.376.0>)
16MB, max heap: 8MB, pool: riak_kv_js_map) host starting (<0.377.0>)
16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.379.0>)
16MB, max heap: 8MB, pool: riak_kv_js_hook) host starting (<0.386.0>)
16MB, max heap: 8MB, pool: riak_kv_js_hook) host starting (<0.387.0>)
2012-07-11 03:33:50.802 [info] <0.7.0> Application bitcask started on node '[email protected]'
2012-07-11 03:33:50.855 [info] <0.463.0>@riak_core:wait_for_application:396 Waiting for
application riak_kv to start (0 seconds).
2012-07-11 03:33:50.862 [info] <0.7.0> Application riak_kv started on node '[email protected]'
2012-07-11 03:33:50.865 [info] <0.7.0> Application riak_search started on node
'[email protected]'
2012-07-11 03:33:50.865 [info] <0.7.0> Application basho_stats started on node
'[email protected]'
2012-07-11 03:33:50.880 [info] <0.7.0> Application runtime_tools started on node
'[email protected]'
2012-07-11 03:33:50.957 [info] <0.463.0>@riak_core:wait_for_application:390 Wait complete for
application riak_kv (0 seconds)
2012-07-11 03:33:51.258 [info] <0.308.0>@riak_core:wait_for_service:410 Wait complete for
service riak_kv (0 seconds)

View Slide

Let's ignore the format for a
moment

View Slide

Logs are just events. Events
with context.

View Slide

So what is Logstash?

View Slide

Logstash
●
An event processing pipeline
●
Events come in (input plugins)
●
Events get analyzed (filter plugins)
●
Events go out (output plugins)
●
Current stats
●
24 inputs
●
18 filters
●
40 outputs!

View Slide

Even Bill O'Reilly can
explain that!

View Slide

Config sample
(Warning: NOT Ruby)
input {
file {
type => "haproxy-log"
path =>
["/var/log/haproxy/haproxy.log"]
sincedb_path =>
"/opt/logstash/agent/etc/"
}
}

View Slide

Inputs
●
Line-oriented
●
Supported formats – plain, json, json_event*
●
Converts incoming events to a Ruby hash
●
json_event is essentially to_json on the
event hash

View Slide

Event Hash
{
"@source" => "",
"@type" => "",
"@tags" => [],
"@fields" => {},
"@timestamp" => "event>",
"@source_host" => "hostname>",
"@source_path" => "input>",
"@message" => "the line>"
}

View Slide

Filters
●
The “analysis engine” of Logstash
●
Kind of like a SlapChop
●
This is where the real work is done
●
Grok is OVER 9000!

View Slide

Grok by Example
(Yes, this is important)

View Slide

May 11 06:00:27 localhost haproxy[7829]:
50.18.111.113:43565 [11/May/2012:06:00:26.920] api-fe api-
be/api-b 0/0/0/390/+390 200 +181 - - ---- 10/10/10/5/0 0/0
{} "GET /api/enstratus/2011-12-15/admin/Job HTTP/1.1"

View Slide

filter {
grok {
type => "haproxy-log"
patterns_dir =>
["/opt/logstash/agent/etc/patter
ns/"]
pattern => "%
{ESHAPROXYHTTP}"
add_tag => ["haproxy-event"]
}
}

View Slide

ESHAPROXYHTTP is
really f'ing big
(WARNING: Wall of Text
incoming!)

View Slide

ESHAPROXYCAPTUREDREQUESTHEADERS %
{DATA:request_header_x_forwarded_for}
ESHAPROXYCAPTUREDRESPONSEHEADERS %
{DATA:response_header_content_type}\|%
{DATA:response_header_content_encoding}\|%
{DATA:response_header_cache_control}\|%
{DATA:response_header_last_modified}
ESHAPROXYHTTP %{SYSLOGTIMESTAMP:syslog_timestamp} %
{IPORHOST:syslog_server} %{SYSLOGPROG}: %{IP:client_ip}:%
{INT:client_port} \[%{HAPROXYDATE:accept_date}\] %
{NOTSPACE:frontend_name} %{NOTSPACE:backend_name}/%
{NOTSPACE:server_name} %{INT:time_request}/%
{INT:time_queue}/%{INT:time_backend_connect}/%
{INT:time_backend_response}/\+%{NOTSPACE:time_duration} %
{INT:http_status_code} \+%{NOTSPACE:bytes_read} %
{DATA:captured_request_cookie} %
{DATA:captured_response_cookie} %
{NOTSPACE:termination_state} %{INT:actconn}/%{INT:feconn}/%
{INT:beconn}/%{INT:srvconn}/%{NOTSPACE:retries} %
{INT:srv_queue}/%{INT:backend_queue} \{%
{ESHAPROXYCAPTUREDREQUESTHEADERS}\} "%{WORD:http_verb} %
{URIPATHPARAM:http_request} HTTP/%{NUMBER:http_version}"

View Slide

May 11 06:00:27
%{SYSLOGTIMESTAMP:syslog_timestamp}
SYSLOGTIMESTAMP %{MONTH} +%{MONTHDAY} %{TIME}
MONTH \b(?:Jan(?:uary)?|Feb(?:ruary)?|
Mar(?:ch)?|Apr(?:il)?|May|Jun(?:e)?|
Jul(?:y)?|Aug(?:ust)?|Sep(?:tember)?|
Oct(?:ober)?|Nov(?:ember)?|Dec(?:ember)?)\b
MONTHDAY (?:(?:0[1-9])|(?:[12][0-9])|
(?:3[01])|[1-9])
TIME (?!<[0-9])%{HOUR}:%{MINUTE}(?::%
{SECOND})(?![0-9])
HOUR (?:2[0123]|[01][0-9])
MINUTE (?:[0-5][0-9])
SECOND (?:(?:[0-5][0-9]|60)(?:[.,][0-9]+)?)

View Slide

May 11 06:00:27
MONTH \b(?:Jan(?:uary)?|Feb(?:ruary)?|Mar(?:ch)?|
Apr(?:il)?|May|Jun(?:e)?|Jul(?:y)?|Aug(?:ust)?|
Sep(?:tember)?|Oct(?:ober)?|Nov(?:ember)?|
Dec(?:ember)?)\b
MONTHDAY (?:(?:0[1-9])|(?:[12][0-9])|(?:3[01])|
[1-9])
TIME (?!<[0-9])%{HOUR}:%{MINUTE}(?::%{SECOND})(?!
[0-9])
HOUR (?:2[0123]|[01][0-9])
MINUTE (?:[0-5][0-9])
SECOND (?:(?:[0-5][0-9]|60)(?:[.,][0-9]+)?)

View Slide

May 11 06:00:27
MONTH \b(?:Jan(?:uary)?|Feb(?:ruary)?|
Mar(?:ch)?|Apr(?:il)?|May|Jun(?:e)?|
Jul(?:y)?|Aug(?:ust)?|Sep(?:tember)?|
Oct(?:ober)?|Nov(?:ember)?|Dec(?:ember)?)\b
MONTHDAY (?:(?:0[1-9])|(?:[12][0-9])|
(?:3[01])|[1-9])
TIME (?!<[0-9])%{HOUR}:%{MINUTE}(?::%
{SECOND})(?![0-9])
HOUR (?:2[0123]|[01][0-9])
MINUTE (?:[0-5][0-9])
SECOND (?:(?:[0-5][0-9]|60)(?:[.,][0-9]+)?)

View Slide

Named Fields
When you identify something it's added to the event hash at the @fields key
{
"@source" => "",
"@type" => "",
"@tags" => [“haproxy_event”],
"@fields" => {“syslog_timestamp” => “May 11 06:00:27”},
"@timestamp" => "",
"@source_host" => "",
"@source_path" => "",
"@message" => ""
}

View Slide

Rinse and Repeat
●
Filters are processed in order
●
Once a field is identified, can be used in
interpolation later
●
%{syslog_timestamp}
●
%{@type}
●
@ fields are special but not sacred.
●
date and mutate filters for instance.

View Slide

Outputs
●
An event can be routed to all or a subset of
defined outputs based on various criteria
●
Outputs block (sort of)
●
Logstash takes a default position that you don't
want to lose an event
●
1 thread per defined output each
●
ALWAYS use a stdout output for debugging
●
Leverage variables for great justice
●
This is where it gets REALLY cool

View Slide

Simplest output
output {
stdout => {
debug => true
debug_format => “json”
}
}

View Slide

ElasticSearch

View Slide

Graphite
output {
graphite { host => "10.1.1.217" metrics =>
[ "stats.enstratus.apps.api.requests.version.
%{es_api_version}", "1"] tags => ["haproxy-
event"]}
graphite { host => "10.1.1.217" metrics =>
[ "stats.enstratus.apps.api.requests.%
{es_api_scope}.%{es_api_object}", "1"] tags
=> ["haproxy-event"]}
}

View Slide

Graphite

View Slide

Boundary

View Slide

DataDog

View Slide

Nagios

View Slide

PagerDuty

View Slide

Remember this guy?

View Slide

He has a thing...

View Slide

Can we get his logs into
Circonus?

View Slide

Challenge Accepted!
output {
circonus {
api_token => "XXXXXXXXXXXXXX"
app_name => "logstash-testing"
annotation => ["title", "Logstash
test", "description", "%{@message}",
"category", "logstash"]
}

View Slide

View Slide

You can still write to files if you want
file {
path => "/var/log/logstash/%
{@source_host}/%{application}"
message_format => "%{@timestamp} %
{@message}"
}

View Slide

Or you can write to ALL the things!

View Slide

Questions?
●
http://github.com/logstash/logstash
●
http://cookbook.logstash.net
●
http://logstash.net
●
@logstash
●
@jordansissel/@fetep/@lusis

View Slide

A Boy and His Logs

A Boy and His Logs

John Vincent

More Decks by John Vincent

Other Decks in Technology

Featured

Transcript