ITSA Blog

This morning I needed to audit some log files that I had recently processed through AWstats and received a report that there was a discrepancy in the data. The complaint was that one day was missing. I used the following bash script to print out the start and end timestamp of each log file:

for file in $( ls -tr *.gz ) ;
do
  BEGIN=$(zcat ${file} | head -n 1 | awk '{print $4}');
  END=$(zcat ${file} | tail -n 1 | awk '{print $4}');
  echo "${file} - ${BEGIN} - ${END}";
done

Note that each log file was named uniquely by web server and logrotate number, eg webserver1.access_log.XX.gz.

Here is a quick awk command that will parse apache web logs and print a simple virtual host/date/referral csv report that only includes referrals from google, bing, or yahoo:

awk 'tolower($11) ~ "google|bing|yahoo" {print $2 "," $4 "," $11}' ${input_file} >> report.csv

Having recently upgraded the Virtual Infrastructure at work to vSphere, I have encountered many scenarios with CentOS 5.3 guests not booting or taking a long time to boot. The last message on the console typically indicates that it’s hanging while starting udev.

The fix for this issue is to ensure proper time keeping practices have been adhered to in accordance with the VMware Timekeeping KB.

The basic steps are:
1. Modify the kernel line of /boot/grub/grub.conf to include the following line:

clocksource=acpi_pm notsc divider=10

clocksource=acpi_pm – uses the Power Management Timer (PMTMR) available in some southbridges as primary timing source
notsc – disable the timestamp counter
divider=10 – reduces the frequency of timer interrupts by 10 (from 1000/second to 100/second)

2. Disable time sync through VMware tools (note that this will continue to happen on bootup, pause, resume, etc..):

vmware-guestd --cmd "vmx.set_option synctime 1 0"

3. Setup time sync through NTP:
a. Setup your /etc/ntp.conf to point to a good NTP server pool.
b. Set NTP to start and persist across reboots.

# yum -y install ntp
# chkconfig ntpd on
# /etc/init.d/ntpd start

One problem that I’ve had with Fedora 12 is that when enabling compliz the focus starts to follow the mouse pointer. This behavior is annoying to me as I don’t like events to occur unless I explicitly ask for them (aka click).

To disable this feature, perform the following:
1. install control-center-extra
2. Open with Applications -> System Tools -> Configuration Editor
3. Select the checkbox at /apps/compiz/general/allscreens/options/click_to_focus

That worked for me.

I was auditing a set of mail servers at work the other day getting a list of all active user accounts and developed this little one liner:

zgrep LOGIN /var/log/mail.log.[1-9].gz | sed -n 's/.*user=\(.*\), ip.*/\L\1/p' | sort | uniq >> /tmp/mailbox.list

This script finds all logins from the mail log and prints out only the account@domain portion in lowercase sorting and printing one of each occurrence.

I’m currently trying to prune a MyISAM table with 200 million rows down to 100 million rows. As part of this process, I am simply removing any orphaned records. This is a simple tracking table where every record must have an associated record in the users table. The total size on disk is 11G of index data and 9G of table data.

The basic process to prune this table is to:
1. setup replication slave for this purpose
2. batch deletes from the table throughout the day
3. run optimize on the table each night

I was surprised to come in this morning to find that the optimize that I had started last night at 6PM had not finished yet. Looking on the server, there was no load, no swapping, no disk I/O, nothing. It was as if MySQL had fallen asleep at the wheel. I looked at the MySQL error log and discovered the problem, /tmp was full.

-0- josh@mysql-server04 /var/lib/mysql >
> tail /var/log/mysql/mysql.err
100210  7:38:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  7:48:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  7:58:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  8:08:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  8:18:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  8:28:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  8:38:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  8:48:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  8:58:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs
100210  9:08:09 [ERROR] /usr/sbin/mysqld: Disk is full writing '/tmp/STJSSGYU' (Errcode: 28). Waiting for someone to free space... Retry in 60 secs

The disk had been full since 4:00 AM and had been blocking on this. I quickly ran a df -h and confirmed that the disk was full, then extended the logical volume by 2G to make a total of 4G of space and MySQL continued to process the optimize.

-0- josh@mysql-server04 ~ >
> sudo lvextend -L +2G /dev/vg01/lvol03
  Extending logical volume lvol03 to 3.97 GB
  Logical volume lvol03 successfully resized

-0- josh@mysql-server04 ~ >
> resize2fs !$
resize2fs /dev/vg01/lvol03
resize2fs 1.39 (29-May-2006)
Filesystem at /dev/vg01/lvol03 is mounted on /tmp; on-line resizing required
Performing an on-line resize of /dev/vg01/lvol03 to 1040384 (4k) blocks.
The filesystem on /dev/vg01/lvol03 is now 1040384 blocks long.

I was then curious to see the files that were in /tmp and listed the contents to find nothing there.

-0- josh@mysql-server04 /tmp >
> find .
.
./.winbindd
./.winbindd/pipe
./.ICE-unix
./lost+found

I then issued another ‘df -h’ to find that the volume was 88% full. Something didn’t add up here. The next step is to use ‘lsof’ to find any deleted files that had not been synced to disk yet.

-0- josh@mysql-server04 /tmp >
> lsof | grep -i delet
mysqld     1404     mysql    7u      REG              253,2           0         12 /tmp/ibERGn68 (deleted)
mysqld     1404     mysql    8u      REG              253,2           0         13 /tmp/ibX1mdbt (deleted)
mysqld     1404     mysql    9u      REG              253,2           0         14 /tmp/ibjjh3fN (deleted)
mysqld     1404     mysql   10u      REG              253,2           0         15 /tmp/ibjHbE38 (deleted)
mysqld     1404     mysql   14u      REG              253,2           0         16 /tmp/ib3F6Tfw (deleted)
mysqld     1404     mysql   68u      REG              253,2  3385629393         17 /tmp/STJSSGYU (deleted)
hald-addo  5043 haldaemon  txt       REG              253,3       15720     258081 /usr/libexec/hald-addon-keyboard.#prelink#.RmsJR9 (deleted)
hald-addo  5046 haldaemon  txt       REG              253,3       15720     258081 /usr/libexec/hald-addon-keyboard.#prelink#.RmsJR9 (deleted)
hald-addo  5050 haldaemon  txt       REG              253,3       15720     258081 /usr/libexec/hald-addon-keyboard.#prelink#.RmsJR9 (deleted)

There is the culprit! We have a large file being used by MySQL although it’s been deleted and not synced to disk yet. That explains everything.

Note to self: ensure the /tmp directory on large MySQL servers is greater than the value of myisam_max_sort_file_size. On this server I had this value set to 10G while the /tmp directory volume was 2G.

I often run into issues on the command line where I’d like to perform a non-greedy search and replace. This is not possible with sed, grep, or egrep, AFAIK, so I must resort to perl. Here is how it’s done:

perl -pe 's|"http://(.*?)/.*$|$1|g' 

The above example will take a list of requested URIs or search domains from an apache log and print out only the domain. I’m using pipes instead of slashes in the regex to eliminate the need to escape the slashes.

Note the question mark used to make a non-greedy match.