Using Logs to Help You Stop Your App from Doing Dumb Things
David Stockton
Zendcon 2013
How it all started.
Debugging a login problem
Put a log line in the user model constructor
public function __construct()
{
…
Log::info(
‘Instantiated User Model.’
);
}
Try a
bad username
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Attempted login by unknown user ‘foobar’
Try a
bad password
WTH?
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Login attempt failed. Bad password for ‘legit user’
Successful Login?
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Instantiated User Model.
[INFO] Login successful: ‘Legit User’
That’s a lot of users!
How to implement?
Make it easy to add logs
Add logs.
Read / Analyze
logstash
splunk
graylog2
Logging Levels
Log at the appropriate levels
Filter Logs on Need
Real-time Application Logging
FireBug with FirePHP
Secure FirePHP
Find Security Problems with Logs
[INFO] Successful login ‘rjames’
[INFO] Successful login ‘cmurphy’
[INFO] Invalid login attempt: ‘dchappelle’
[INFO] Invalid login attempt: ‘dchappelle’
[INFO] Invalid login attempt: ‘dchappelle’
[INFO] Invalid login attempt: ‘dchappelle’
[INFO] Invalid login attempt: ‘dchappelle’
[INFO] User account ‘dchappelle’ locked.
[INFO] Successful login ‘dchappelle’
[INFO] Successful login ‘slaurel’
[INFO] Successful login ‘ohardy’
[INFO] Successful login ‘fbase OR 1=1’
Frontend Validation
Filter Input
Backend Logging / Intrusion Detection
[INFO] Successful login ‘tcruise’
[INFO] Successful login ‘cgoodingjr’
[INFO] Invalid login attempt: ‘rzellweger OR 1=1’ - Possible Intrusion Attempt
[INFO] Invalid login attempt: ‘rzellweger AND 1=1’ - Possible Intrusion Attempt
[INFO] Invalid login attempt: ‘’ OR 1=1 ;-- ’ - Possible Intrusion Attempt
Beware Log Injection
[INFO] Successful login ‘tcruise’
[INFO] Successful login ‘cgoodingjr’
[WARN] Invalid login attempt: ‘rzellweger OR 1=1’ - Possible Intrusion Attempt
[WARN] Invalid login attempt: ‘rzellweger AND 1=1’ - Possible Intrusion Attempt
[WARN] Invalid login attempt: ‘’
[INFO] Successful login ‘joconnell OR 1=1 ;-- ’ - Possible Intrusion Attempt
[INFO] Successful login ‘tcruise’
[INFO] Successful login ‘cgoodingjr’
[WARN] Invalid login attempt: ‘rzellweger OR 1=1’ - Possible Intrusion Attempt
[WARN] Invalid login attempt: ‘rzellweger AND 1=1’ - Possible Intrusion Attempt
[WARN] Invalid login attempt: ‘’
[INFO] Successful login ‘joconnell OR 1=1 ;-- ’ - Possible Intrusion Attempt
try {
// some code
} catch (\SomeException $e) {
if ($e->likelyScenario()) {
// do regular recovery
} else if ($e->unlikely()) {
// do crazy recovery
} else {
// Never going to happen
}
}
Log the impossible happening
0.01% of 1M is 100.
Log the impossible happening
0.0001 of 1M is 100.
Syncing Time
Correlate Logs from Different Servers
Syncing Time
Syncing Time
[App] 12:02:03 - Call to member query on non-object …
[App] 12:02:03 - Other App related logs
...
[DB] 12:02:00 - MySql: Normal shutdown
[DB] 12:02:01 - MySql: Forcing close of thread 1 user: 'root'
[DB] 12:02:03 - InnoDB: Starting shutdown...
[DB] 12:02:04 - InnoDB: Shutdown completed
Aggregating
[DB] 12:02:00 - MySql: Normal shutdown
[DB] 12:02:01 - MySql: Forcing close of thread 1 user: 'root'
[App] 12:02:03 - PHP Error: Call to member “query” on non-object
[DB] 12:02:03 - InnoDB: Starting shutdown...
[DB] 12:02:04 - InnoDB: Shutdown completed
php.ini
display_errors = Off
log_level = E_ALL; #E_ALL & ^E_NOTICE prod
error_log = /path/to/logs
Another Story
Sending SMS
Hey, I noticed you. Check out my profile on spamdate.net
Hello, I noticed you. View my profile on boxofdates.net
Analyzed logs
Built tool to stop the SPAM
Escalating Punishment Schedule
1st time - blocked for 5 minutes
2nd time - blocked for 10 minutes
3rd level - blocked for 30 minutes
4th level - banned.
Crisis Averted
Back to logging
set_error_handler(...)
Handle errors appropriately
set_exception_handler(...)
Log exception traces
Review logs in pre-prod, fix issues
Review logs in prod, fix issues
Strive for error-free production logs
After You’ve
Added Logging
Learn Normal Flow Through App
Notice weird paths through app
Identify session/request in logs
Build tools to help analyze logs
Use them.
Another story
Store searches
Google Maps API rate limiting
Store search based on zip code
Mapped location of queries
$zips = range(
‘00000’, ‘99999’
);
for ($zip in $zips) {
// spam site with $zip
}
// Disclaimer: Code for illustration purposes.
// Doesn’t do what we want
Slowed down bot requests, serve real customers
Crisis Averted
Take advantage of your logs
Let them help you stop your application from doing dumb things
Questions?
Please rate this talk
http://joind.in/9104