Logging in MySQL

Scope:

This article demonstrates logging techniques in MySQL to uncover and analyze any mischief attempts done by (outside or inside) user focusing on specific areas in database.

Getting Started:

Following are the types of logs available in MySQL^[1].

Log Type	Information Written to Log
Error log	Problems encountered starting, running, or stopping mysqld
General query log	Established client connections and statements received from clients
Binary log	Statements that change data (also used for replication)
Relay log	Data changes received from a replication master server
Slow query log	Queries that took more than long_query_time seconds to execute

By Default, logging is not enabled in MySQL.  To enable that use command “show processlist”.

mysql>show processlist;

Note:  This shows all running queries.  Info column in result shows the query which is executed.

Now this is only showing data for current session.  If you want to see all the queries being executed on the server then you should log them first.

We have seen different types of logging in MySQL, so which one to use? We will use General Log, which will give us all the queries executed at the server.

How to go about it?

• Check logging is enabled or not
• What type of logging is enabled (FILE, TABLE, BOTH)?
• If not enabled, how to enable it?
• What to check?

Simply log into the MySQL prompt and issue following command

mysql> show variables;

This will list all the global variables in MySQL. Look for general_log variable and its value; Ideally if logging is not enabled then its value would be “OFF” and general_log_file variable would be:

For *NIX: “/var/lib/mysql/mysql.log”

For Windows (XAMPP setup):  “C:\xampp\mysql\data\<system_name>.log”

• You can determine whether logging is of what type by looking output of following variable.
  log_output = ‘FILE|TABLE|BOTH’

• You can change the value of this using following command
  mysql> SET GLOBAL log_output = ‘FILE’;

As logging is not enabled, let’s enable that first. To do that, issue the following command.

mysql>SET GLOBAL general_log = ‘ON’;

mysql>SET GLOBAL general_log_file = ‘path_on_your_system’;

Similarly you can set the logging for slow query log.

mysql>SET GLOBAL slow_query_log = ‘ON’;

mysql>SET GLOBAL slow_query_log_file = ‘path_on_your_system’;

Slow query logs are basically those which took longer time to execute then specified value in “long_query_time”

So, we have all the required logs. What Next?

Let’s Analyze.

What could be wrong?

• It could be attack from web, most common being SQL Injection
• What about somebody from inside? Privilege escalation or data stealing?

In both the cases, who did it? Let’s find out….

Case 1:

Suppose, somebody got a weak link in the application, and got into the system by some SQL Injection. I don’t have to explain what is SQL Injection is, well I may can tell you what someone can do with SQL Injection.  For the attacker, there can be only one entry point, but in backend there are many things, like web server, database server, etc.

Let’s look at web server log (in our case its apache logs). During normal operations, things would look pretty simple and straight forward. At the glance it looks neat and clean.

Let’s search for something, like “select”, if anyone is trying to run a SQL query

Similarly we can search for “union” or any other such SQL command to see if there is any suspicious activity is going on.

It is Interesting to see that we have some requests which have SQL queries in the request parameters. This indicates that there is something suspicious about these requests as timestamp is same for few queries. It simply means attacker has run an automated scanner to exploit the vulnerability.

Suspicious log snippet:

127.0.0.1 - - [14/Sep/2012:15:45:10 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+%28select+concat%280x7e%2C0x27%2C0x7233646D3076335F68766A5F696E6A656374696F6E%2C0x27%2C0x7e%29+limit+0%2C1%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 54 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:45:10 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28database%28%29+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 42 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:46:05 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28user%28%29+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 47 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:46:05 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28version%28%29+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 39 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:46:05 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28database%28%29+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 42 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:46:05 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28system_user%28%29+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 47 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:46:05 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28%40%40hostname+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 42 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

127.0.0.1 - - [14/Sep/2012:15:46:05 +0530] "GET /sqli.php?u=999999.9%27+union+all+select+concat%280x7e%2C0x27%2Cunhex%28Hex%28cast%28%40%40basedir+as+char%29%29%29%2C0x27%2C0x7e%29%2C0x31303235343830303536+and+%27x%27%3D%27x HTTP/1.1" 200 47 "-" "Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; SV1; .NET CLR 2.0.50727)”

Once you are sure that there is an incident of SQL Injection by an unknown IP then you can proceed with the formal procedure of investigating this issue with cyber cell.

Case 2:

Now let’s consider the second case, where MySQL user who has access to database has done some mischiefs. Popular activities possible are:

• Running privileges escalation attacks
• Getting root password (will see how)
• Dumping database(s) into files

Note: There are few privilege escalation attacks available in Metasploit also.

For getting the root password is fairly simple. A low privilege user just has to execute following command on the prompt.

mysql> SELECT LOAD_FILE(‘C:\xampp\mysql\data\mysql\user.MYD’);

Note: The path will change as per the setup.

If you are not getting any result then you should have physical access to this file, ssh, RDP, etc. Basically we just need data of this file.

This is a binary file containing the MySQL user information with username and password. So if you are root user then you can simply run following query to see all users. 

mysql> select Host, User, Password from mysql.user;

When low privilege user (fdb in our case) tries to run this query, obviously he will get access denied error. At this instance our previous query will be handy, reading binary file. So, what is the problem now? Simple, the password is stored in MD5 hashJ. Cracking this would not take much time.

Note: Tools like md5crack, John the Ripper, Cain & Adel do a fine job of cracking MD5 hashes.

Considering the last part, where user is dumping the database into file for some notorious purpose, we can check the same in our general_log or slow_query_log for such queries. In this case we are opening this log file in and we will do some manual analysis first.

Here is snippet of the query log:

325 Connect   root@localhost on

325 Init DB   forensics

325 Query     SELECT * FROM forensics_test where uname = '999999.9' union all select (select distinct concat(0x7e,0x27,unhex(Hex(cast(schema_name as char))),0x27,0x7e) from `information_schema`.schemata limit 3,1),0x31303235343830303536 and 'x'='x'

325 Quit

326 Connect   root@localhost on

326 Init DB   forensics

326 Query     SELECT * FROM forensics_test where uname = '999999.9' union all select (select distinct concat(0x7e,0x27,unhex(Hex(cast(schema_name as char))),0x27,0x7e) from `information_schema`.schemata limit 4,1),0x31303235343830303536 and 'x'='x'

326 Quit

327 Connect   root@localhost on

327 Init DB   forensics

327 Query     SELECT * FROM forensics_test where uname = '999999.9' union all select (select distinct concat(0x7e,0x27,unhex(Hex(cast(schema_name as char))),0x27,0x7e) from `information_schema`.schemata limit 5,1),0x31303235343830303536 and 'x'='x'

327 Quit

328 Connect   root@localhost on

328 Init DB   forensics

328 Query     SELECT * FROM forensics_test where uname = '999999.9' union all select (select distinct concat(0x7e,0x27,unhex(Hex(cast(schema_name as char))),0x27,0x7e) from `information_schema`.schemata limit 6,1),0x31303235343830303536 and 'x'='x'

328 Quit

329 Connect   root@localhost on

329 Init DB   forensics

329 Query     SELECT * FROM forensics_test where uname = '999999.9' union all select (select distinct concat(0x7e,0x27,unhex(Hex(cast(schema_name as char))),0x27,0x7e) from `information_schema`.schemata limit 7,1),0x31303235343830303536 and 'x'='x'

329 Quit

330 Connect   root@localhost on

330 Init DB   forensics

330 Query     SELECT * FROM forensics_test where uname = '999999.9' union all select (select distinct concat(0x7e,0x27,unhex(Hex(cast(schema_name as char))),0x27,0x7e) from `information_schema`.schemata limit 8,1),0x31303235343830303536 and 'x'='x'

330 Quit

What we basically search is statements like “union select”, query to “information_schema” database, query to “mysql” database, etc. Then analyze it further to conclude on a result.

Conclusion

Only logging will not do the job, it is also important to do analysis after that. Frequently, database administrator(s) only enable logging features, and leave just like that. But the actual analysis behind it is much more important. One thing that I shouldn’t be mentioning is that, using this technique you can extract all the queries used by an automated scanner like, Havij, SQLMap, etc. I personally do not recommend that, but once you know the queries these tools run you will better understand SQL Injection.

References:

1. http://dev.mysql.com/doc/refman/5.1/en/server-logs.html