Upgrade to Pro — share decks privately, control downloads, hide ads and more …

A Boy and His Logs

A Boy and His Logs

Presentation for DevOpsATL 07/11/2012

6385d06011a9633cd45cab0662ae9eb8?s=128

John Vincent

July 12, 2012
Tweet

Transcript

  1. A boy and his logs John E. Vincent (@lusis) DevOpsATL

    7/11/12
  2. Let me tell you a story about a boy....

  3. None
  4. He's got logs over here..

  5. Huge logs...

  6. Can't make any sense of them...

  7. (Probably came from a Node app)

  8. There's a lot of data in these logs

  9. He just wants to get the over here

  10. Maybe analyze them?

  11. It's cool, man..

  12. Logstash makes logging sexy

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

  14. What is Logstash?

  15. Let's answer a different question first...

  16. What are logs?

  17. 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 Jul 11 09:07:40 jvstratusmbp login[23266]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800. Jul 11 09:07:40 jvstratusmbp login[23266]: in od_record_check_pwpolicy(): retval: 0 Jul 11 09:07:40 jvstratusmbp login[23266]: in od_record_attribute_create_cfstring(): returned 2 attributes for dsAttrTypeStandard:AuthenticationAuthority Jul 11 09:13:51 jvstratusmbp login[23333]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800. Jul 11 09:13:51 jvstratusmbp login[23333]: in od_record_check_pwpolicy(): retval: 0 Jul 11 09:13:51 jvstratusmbp login[23333]: in od_record_attribute_create_cfstring(): returned 2 attributes for dsAttrTypeStandard:AuthenticationAuthority Jul 11 09:28:41 jvstratusmbp login[23416]: in pam_sm_acct_mgmt(): OpenDirectory - Membership cache TTL set to 1800. Jul 11 09:28:41 jvstratusmbp login[23416]: in od_record_check_pwpolicy(): retval: 0 Jul 11 09:28:41 jvstratusmbp login[23416]: in od_record_attribute_create_cfstring(): returned 2 attributes for dsAttrTypeStandard:AuthenticationAuthority
  18. 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 com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2280) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2265) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(Delegating PreparedStatement.java:105) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(Delegating PreparedStatement.java:105)
  19. [11 Jul 2012 00:08:42.066] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`,

    `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.116] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.105] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.105] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.140] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:39:02.078] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `provider_rdbms`.`admin_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`.`enstratus_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` = ?
  20. [11 Jul 2012 00:08:42.066] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`,

    `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.116] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.105] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.105] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:08:42.140] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `region`.`account`, `region`.`active`, `region`.`keypair`, `region`.`provider_region`, `region`.`provider_region_id`, `region`.`region_id` FROM `region` WHERE `region`.`account` = ? ORDER BY `region`.`provider_region_id` [11 Jul 2012 00:39:02.078] [WARN.org.dasein.persist.jdbc.Loader] SLOW QUERY: SELECT `provider_rdbms`.`admin_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`.`enstratus_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` = ?
  21. 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" Jul 11 06:24:27 localhost haproxy[953]: 127.0.0.1:48044 [11/Jul/2012:06:24:25.601] api-fe 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" Jul 11 06:24:27 localhost haproxy[953]: 127.0.0.1:48042 [11/Jul/2012:06:24:25.412] api-fe api-be/api-c 0/0/0/2389/+2389 204 +89 - - ---- 9/9/7/4/0 0/0 {50.18.111.113} "DELETE /api/enstratus/2012-02-29/infrastructure/Snapshot/20861069 HTTP/1.1" Jul 11 06:24:27 localhost haproxy[953]: 127.0.0.1:48046 [11/Jul/2012:06:24:26.092] api-fe api-be/api-c 0/0/0/1880/+1880 204 +89 - - ---- 9/9/6/3/0 0/0 {50.18.111.113} "DELETE /api/enstratus/2012-02-29/infrastructure/Snapshot/20908906 HTTP/1.1" Jul 11 06:24:29 localhost haproxy[953]: 127.0.0.1:48048 [11/Jul/2012:06:24:27.409] api-fe api-be/api-b 0/0/0/2000/+2000 204 +89 - - ---- 7/7/7/4/0 0/0 {50.18.111.113} "DELETE /api/enstratus/2012-02-29/infrastructure/Snapshot/20908912 HTTP/1.1" Jul 11 06:24:30 localhost haproxy[953]: 127.0.0.1:47965 [11/Jul/2012:06:14:30.013] api-fe 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/enstratus/2012-02-29/infrastructure/Snapshot?regionId=7141&volumeId=148762 HTTP/1.1" Jul 11 06:24:30 localhost haproxy[953]: 127.0.0.1:47967 [11/Jul/2012:06:14:30.729] api-fe 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/enstratus/2012-02-29/infrastructure/Snapshot?regionId=68&volumeId=133383 HTTP/1.1" Jul 11 06:24:30 localhost haproxy[953]: 127.0.0.1:47969 [11/Jul/2012:06:14:30.868] api-fe api-be/api-b 0/0/0/-1/+600002 504 +194 - - sH-- 3/3/3/1/0 0/0 {50.18.111.113} "GET /api/enstratus/2012-02-29/infrastructure/Snapshot?regionId=68&volumeId=102312 HTTP/1.1" Jul 11 06:24:31 localhost haproxy[953]: 127.0.0.1:48050 [11/Jul/2012:06:24:28.820] api-fe
  22. 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" Jul 4 02:10:42 lb-api-a pound: api.enstratus.com 24.118.90.130 - - [04/Jul/2012:02:10:42 +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" Jul 4 02:10:46 lb-api-a pound: api.enstratus.com 24.118.90.130 - - [04/Jul/2012:02:10:46 +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" Jul 4 02:10:49 lb-api-a pound: api.enstratus.com 24.118.90.130 - - [04/Jul/2012:02:10:49 +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" Jul 4 04:46:27 lb-api-a pound: api.enstratus.com 58.160.169.245 - - [04/Jul/2012:04:46:22 +0000] "GET /api/enstratus/2012-02-29/infrastructure/ Server?activeOnly=false HTTP/1.1" 200 19933 "" "enstratus.rb" Jul 4 04:47:15 lb-api-a pound: api.enstratus.com 58.160.169.245 - - [04/Jul/2012:04:46:39 +0000] "GET /api/enstratus/2012-02-29/infrastructure/ Server?activeOnly=false HTTP/1.1" 200 97563 "" "enstratus.rb"
  23. 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>) 2012-07-11 03:33:50.750 [info] <0.377.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_map) host starting (<0.377.0>) 2012-07-11 03:33:50.755 [info] <0.379.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.379.0>) 2012-07-11 03:33:50.759 [info] <0.380.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.380.0>) 2012-07-11 03:33:50.763 [info] <0.381.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.381.0>) 2012-07-11 03:33:50.767 [info] <0.382.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.382.0>) 2012-07-11 03:33:50.772 [info] <0.383.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.383.0>) 2012-07-11 03:33:50.776 [info] <0.384.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_reduce) host starting (<0.384.0>) 2012-07-11 03:33:50.781 [info] <0.386.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 16MB, max heap: 8MB, pool: riak_kv_js_hook) host starting (<0.386.0>) 2012-07-11 03:33:50.784 [info] <0.387.0>@riak_kv_js_vm:init:76 Spidermonkey VM (thread stack: 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 'riak@10.1.1.208' 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 'riak@10.1.1.208' 2012-07-11 03:33:50.865 [info] <0.7.0> Application riak_search started on node 'riak@10.1.1.208' 2012-07-11 03:33:50.865 [info] <0.7.0> Application basho_stats started on node 'riak@10.1.1.208' 2012-07-11 03:33:50.880 [info] <0.7.0> Application runtime_tools started on node 'riak@10.1.1.208' 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)
  24. Let's ignore the format for a moment

  25. Logs are just events. Events with context.

  26. So what is Logstash?

  27. 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!
  28. Even Bill O'Reilly can explain that!

  29. Config sample (Warning: NOT Ruby) input { file { type

    => "haproxy-log" path => ["/var/log/haproxy/haproxy.log"] sincedb_path => "/opt/logstash/agent/etc/" } }
  30. 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
  31. Event Hash { "@source" => "<format determined by input>", "@type"

    => "<type from input>", "@tags" => [], "@fields" => {}, "@timestamp" => "<ISO8601 of received event>", "@source_host" => "<localhost or source hostname>", "@source_path" => "<value determined by input>", "@message" => "<the escaped representation of the line>" }
  32. Filters • The “analysis engine” of Logstash • Kind of

    like a SlapChop • This is where the real work is done • Grok is OVER 9000!
  33. Grok by Example (Yes, this is important)

  34. 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"
  35. 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"
  36. filter { grok { type => "haproxy-log" patterns_dir => ["/opt/logstash/agent/etc/patter

    ns/"] pattern => "% {ESHAPROXYHTTP}" add_tag => ["haproxy-event"] } }
  37. ESHAPROXYHTTP is really f'ing big (WARNING: Wall of Text incoming!)

  38. 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}"
  39. 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}"
  40. 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]+)?)
  41. 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]+)?)
  42. 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]+)?)
  43. 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]+)?)
  44. Named Fields When you identify something it's added to the

    event hash at the @fields key { "@source" => "<format determined by input>", "@type" => "<type from input>", "@tags" => [“haproxy_event”], "@fields" => {“syslog_timestamp” => “May 11 06:00:27”}, "@timestamp" => "<ISO8601 of received event>", "@source_host" => "<localhost or source hostname>", "@source_path" => "<value determined by input>", "@message" => "<the escaped representation of the line>" }
  45. 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.
  46. 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
  47. Simplest output output { stdout => { debug => true

    debug_format => “json” } }
  48. ElasticSearch

  49. 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"]} }
  50. Graphite

  51. Graphite

  52. Boundary

  53. DataDog

  54. Nagios

  55. PagerDuty

  56. Remember this guy?

  57. He has a thing...

  58. Can we get his logs into Circonus?

  59. Challenge Accepted! output { circonus { api_token => "XXXXXXXXXXXXXX" app_name

    => "logstash-testing" annotation => ["title", "Logstash test", "description", "%{@message}", "category", "logstash"] }
  60. None
  61. You can still write to files if you want file

    { path => "/var/log/logstash/% {@source_host}/%{application}" message_format => "%{@timestamp} % {@message}" }
  62. Or you can write to ALL the things!

  63. Questions? • http://github.com/logstash/logstash • http://cookbook.logstash.net • http://logstash.net • @logstash •

    @jordansissel/@fetep/@lusis