Log Rotation to NFS Mount with Logrotate.d

Logrotate.d is one of the most flexible log rotation programs for linux servers. I recently was required to rotate a lot of large files daily from the server to a central NFS Mount and wanted to share just how easy this is to accomplish.

As background, this app is a Node.js application that uses Bunyon for a logging output plugin. Luckily, it accepts a USR2 signal to tell it "hey, I just rotated your log file, make a new one and keep on truckin'". See, the first issue is that moving a file that a process is writing to, simply renames where the inode is pointing, so your process will continue writing to the new filename as if nothing happened. Telling it to make a new file is key to rotation.

The following code block is the entirety of my logrotate.d script. Placed in the /etc/logrotate.d/ folder, it will be read in and processed every night. I've used the date command to create sub dirs per month to keep things organized in the long term, and the hostname to put them each in their own directories per hostname.

/var/log/myApp/*log {
    daily
    dateext
    rotate 7
    missingok
    compress
    sharedscripts
    postrotate
        [ ! -f /var/run/myApp.pid ] || kill -USR2 `cat /var/run/myApp.pid`
    endscript
    lastaction
 mkdir -p /logsMount/myApp/`hostname`/`date +%Y\/%m`/
 mv /var/log/myApp/*gz /logsMount/myApp/`hostname`/`date +%Y\/%m`/ 
    endscript
}

As this reads, top down: For all files ending in "log" in the /var/log/myApp directory, on a daily basis, throw a date extension on them (-20150102 for instance. Not putting 'dateext' will cause it to simply number them .1, .2, etc.), keep the last 7 days (useful if the nfs mount goes down). If the files are missing don't throw an error. Compress the files (with gzip by default). As your Post Rotate command, send a signal to the process ID noted in the /var/run/myApp.pid file to tell that process to regenerate it's logs. Then, when that's done, make sure there's a directory on the target nfs mount and move all .gz files to it.

It's important to note that the 'postrotate' commans occur AFTER file rotation, but PRIOR to compression. the 'lastaction' section occurs as the last thing it does in this script, i.e. after all other things are done including compression.

This will move things like: /var/log/myApp/myLogFile.log -> /logsMount/myApp/myHost/2015/01/myLogFile.log-20150102.gz

Hope this helps someone out!

LogStash ElasticSearch Index Cleanup

LogStash is a great way to track logs from lots of different sources and store them in a central location where metrics and monitoring can occur. I've started pushing LOTS of data into our setup which uses the ElasticSearch back end. To quote their site, "ElasticSearch is a flexible and powerful open source, distributed, real-time search and analytics engine." and I think it has a really bright future... but currently it's soaking up a lot of disk space. I'm sure I'm not the only one with this issue, after all, when something can handle LOADS of data, you want to give it all you've got! So, we've got 3 hosts running ElasticSearch processes, each with 250GB of data storage. Sometimes one will start to fill up. Looking into the API, I found it's really, REALLY easy to delete old data to keep the size within requested parameters. First off, looking at LogStash's ElasticSearch plugin, it notes that by default LogStash indexes are "logstash-%{+YYYY.MM.dd}". Keeping that in mind, the following info would work for anything as long as you know the indexes you want to delete, but let's start off simple.

curl -s -XDELETE  'http://127.0.0.1:9200/logstash-2014.02.28'

That'll delete the "logstash-2014.02.28" index. I've had to connect in and do this sometimes. Great to do when you need it on demand, but we can do better. Assuming that I'm cool keeping the last 7 days up there, let's edit up a quick bash script:

#!/bin/bash
DATETODELETE=`date +%Y.%m.%d -d '7 days ago'`
curl -s -XDELETE  http://127.0.0.1:9200/logstash-${DATETODELETE}

Now, we could put that in the crontab, have it run once or twice a day and be good to go... And if you knew you could ALWAYS keep 7 days worth of data on your system, that'd be acceptable. But let's have some more fun. Let's assume that we want to keep as much as we can on our system and still keep 10% space free and that the drive we store this on is mounted on /data

#!/bin/bash
#This is about 10% of a 250GB volume (not GiB) using 1000 = k 
DESIRED=24410000
AVAIL=`df /data|grep -v Filesystem|awk '{print $4}'`
if [ $AVAIL -lt $DESIRED ] 
then
    curl -s -XDELETE 127.0.0.1:9200/`curl -s 127.0.0.1:9200/_stats?pretty|grep logstash|sort|awk -F'"' '{ print $2 }'|head -n1`
fi

Let's explain this sample a bit... First off, we set DESIRED to be the amount of "Available" space we desire the system to retain. in our case above, I calculated 10% of a 250GB drive and put that in. So if it ever starts to go below 10% remaining (90%+ used) the if statement will fire.

Next, I pull the Available space. If you take what's in the backquotes and put it on a command line, you'll see what happens. I run df, limited to just the filesystem I care about, I get rid of the line with the labels and then awk pulls out the 4th column (Avail). This number gets stored in AVAIL and we move on.

The If statement then compares the two, if DESIRED is less than AVAIL, we are bumping our limit and have something's got to give, so we run the curl... This curl is a combination of two actually. Starting inside out, we do a "curl -s 127.0.0.1:9200/_stats?pretty" which prints out a list of indexes and a bunch of cool stats about them... then we grep for logstash to get rid of all the cool stats and just keep the names, then we use sort to make sure they're in order of lowest to highest (since they have dates 2014-03-04 and such, that works) and then we use some awk magic to pull out JUST the name of the index and get rid of the other chars 'pretty' uses. That then gets placed back in the right place for the outter curl to execute a delete on it and bye, bye index!

If you put this in your crontab and run it often (it won't do anything if the drive has more than the desired available space remaining) you'll be able to maintain free space on your ElasticSearch hosts without having to set a hard limit on days to keep.

Thinking further into it, you can use the same script with different commands inside the if statement to keep free space on many other systems as well.

Running Custom SNMPd Checks in CentOS 6

I've been fighting with a problem between CentOS 5.x and CentOS 6.x SNMPD configs. In CentOS 5.x we have two lines in /etc/snmpd/snmpd.conf like the following:

exec 1.3.6.1.4.1.5001.100 mailq-check /usr/local/nagios/libexec/check_mailq -w2 -c4 -t7 
exec 1.3.6.1.4.1.5002.1 fscheck /bin/touch /opt/rocheck && /bin/touch /tmp/rocheck

They're simple commands that extend snmp. In CentOS 5.x this form is: "exec <return oid> <name> <command>" and when setup the command or script's output will be returned via snmpd to those that request the MIB/OID. All well and good, but copying this into the standard snmpd.conf file from CentOS 6 gave me nothing. running snmpd with verbose logging gave me nothing useful other than being able to see that it was being requested. Digging deeper, I found the following command and it's output:

# snmpwalk -v 2c 10.93.90.209 -c rsprod .1.3.6.1.4.1.2021.8
UCD-SNMP-MIB::extIndex.1 = INTEGER: 1
UCD-SNMP-MIB::extIndex.2 = INTEGER: 2
UCD-SNMP-MIB::extNames.1 = STRING: 1.3.6.1.4.1.5001.100
UCD-SNMP-MIB::extNames.2 = STRING: 1.3.6.1.4.1.5002.1
UCD-SNMP-MIB::extCommand.1 = STRING: mailq-check
UCD-SNMP-MIB::extCommand.2 = STRING: fscheck
UCD-SNMP-MIB::extResult.1 = INTEGER: 1
UCD-SNMP-MIB::extResult.2 = INTEGER: 1
UCD-SNMP-MIB::extOutput.1 = STRING: mailq-check: No such file or directory
UCD-SNMP-MIB::extOutput.2 = STRING: fscheck: No such file or directory
UCD-SNMP-MIB::extErrFix.1 = INTEGER: 0
UCD-SNMP-MIB::extErrFix.2 = INTEGER: 0
UCD-SNMP-MIB::extErrFixCmd.1 = STRING: 
UCD-SNMP-MIB::extErrFixCmd.2 = STRING: 

Looking at this, it doesn't look like it's running my script "/usr/local/nagios/libexec/check_mailq -w2 -c4 -t7" but attempting to run the name "mailq-check". Of course, that isn't the script name+path, so it doesn't find it. Turns out that in CentOS 6, you don't use the oid portion:

exec mailq-check "/usr/local/nagios/libexec/check_mailq -w2 -c4 -t7 -Mpostfix"
exec fscheck "/bin/touch /opt/rocheck && /bin/touch /tmp/rocheck"

Which, when called with the same snmpwalk above, comes back as:

UCD-SNMP-MIB::extIndex.1 = INTEGER: 1
UCD-SNMP-MIB::extIndex.2 = INTEGER: 2
UCD-SNMP-MIB::extNames.1 = STRING: mailq-check
UCD-SNMP-MIB::extNames.2 = STRING: fscheck
UCD-SNMP-MIB::extCommand.1 = STRING: /usr/local/nagios/libexec/check_mailq -w2 -c4 -t7 -Mpostfix
UCD-SNMP-MIB::extCommand.2 = STRING: /bin/touch /opt/rocheck && /bin/touch /tmp/rocheck
UCD-SNMP-MIB::extResult.1 = INTEGER: 0
UCD-SNMP-MIB::extResult.2 = INTEGER: 0
UCD-SNMP-MIB::extOutput.1 = STRING: OK: mailq reports queue is empty|unsent=0;2;4;0
UCD-SNMP-MIB::extOutput.2 = STRING: 
UCD-SNMP-MIB::extErrFix.1 = INTEGER: 0
UCD-SNMP-MIB::extErrFix.2 = INTEGER: 0
UCD-SNMP-MIB::extErrFixCmd.1 = STRING: 
UCD-SNMP-MIB::extErrFixCmd.2 = STRING: 

Now, let me explain what all of these MIBs mean.

• extIndex.#
  The Index number of the command
• extNames.#
  The Name you gave the command. This is the first parameter you pass to exec
• extCommand.#
  The full command you had SNMPd call to return you this info. Second parameter you passed to exec
• extResult.#
  Exit Code from the command exec'd
• extOutput.#
  Raw output of the command exec'd
• extErrFix.#
  This is a bit that can be flipped by the client. Flipping this to a 1 kicks off the extErrFixCmd by SNMPd. Generally this is used to 'fix' and 'error' condition.
• extErrFixCmd.#
  The command to be executed by the SNMPd server

Restoring MS SQL Analysis Server Database or Cube with Specific ID

Restoring a MS SQL Database in 2008 and later is really easy, but I recently found that it won't always result in the Database having the ID you want it to. In my case, I needed to restore the database next to one that already existed. Upon doing so, it automatically changed the ID of the database to match that of the name I gave it. This is nice, but not what I wanted. I have a lot of jobs that refer to the database by it's ID, and you can't change an ID once it's in place. Furthermore, the restore dialog doesn't give you the option to specify your ID either, however, the Script button does... XMLA Scripts to the rescue!

Step Through It

1. Open up Management Studio
2. Connect to your Analysis Services Server
3. Right Click on the Databases and hit "Restore..."
4. When the Restore window comes up, fill in as much info as you can, but instead of hitting "OK", hit the "Script" button at the top. A new script will open behind your window. Close the window and go to the script, it should look something like this.

<Restore xmlns="http://schemas.microsoft.com/analysisservices/2003/engine">
  <File>\\Gibson\Awesome\AnalysisServices\Awesome_Data\Awesome_Data_20140201030032.abf</File>
  <DatabaseName>Awesome Data New</DatabaseName>
 <DatabaseID>Awesome ID</DatabaseID>
  <AllowOverwrite>true</AllowOverwrite>
</Restore>

Finally, Add that DatabaseID line and Hit F5 to run the restore!

When it's done you should have a newly restored Cube/Database, with the ID you were hoping for!

WordPress asks for FTP Credentials

Being a modern Systems Administrator, I'm sometimes asked to manage things that throw me for a loop. WordPress is one of those things. It's both really simple and really complex, and sometimes not direct with it's response to problems. I've noticed with a fresh WordPress install that when my users wanted to upload a new theme, they were presented with a normal 'upload' link. Click this button, browse to your file, hit okay, then hit upload. All well and good. But then it prompted them for FTP or SFTP credentials. No error message, no reason why FTP would be needed in light of the previous, seemingly successful upload. We don't run FTP here in relation to WordPress, nor would I want to add that complexity to the setup or allow another potential access point for an attacker.

After digging a bit, the reason came down to my being a bit too secure and clamping down the permissions for my web server user, on the WordPress files, too far. I found the following issues during troubleshooting:

• The default install from a tarball doesn't make the wp-content/uploads directory. You've got to make it yourself.
• The uploads dir must allow writes (for obvious reason) by apache or www-user or whoever your web user is.
• The target of your upload has to go somewhere... Theme uploads need apache to be able to write to wp-content/themes/, upgrades wp-content/upgrades/, etc.

Fixing these issues made the FTP prompt stop showing up, and we were good to go.

More OpenShift Oddities

I had to fight with OpenShift a bit more today to get my application up and running after a botched code push. Restarting from the website didn't work, and simply re-pushing git code didn't help either... so time to dig in. As you can see here, [node] being in brackets meant it wasn't really running, it was in the process of starting or stopping... in fact, it kept doing it quite frequently according to a tail -f on /nodejs/logs/node.log ... So, I decided I had to stop it restarting, but how?

[(app name).rhcloud.com (username)]\> ps aux
kUSER        PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
1313     240483  0.0  0.0 105068  3152 ?        S    17:02   0:00 sshd: (user)@pts/1
1313     240486  0.0  0.0 108608  2100 pts/1    Ss   17:02   0:00 /bin/bash --init-file /usr/bin/rhcsh -i
1313     249661  0.1  0.4 397100 35224 ?        Sl   17:08   0:00 /usr/bin/mongod --auth -f /var/lib/openshift/(user)/mongodb//conf/mongodb.conf run
1313     261473  5.5  0.0      0     0 ?        R    17:15   0:00 [node]
1313     261476  2.0  0.0 110244  1156 pts/1    R+   17:15   0:00 ps aux
1313     390906  8.1  0.2 1021240 20196 ?       Sl   Dec10 321:14 node /opt/rh/nodejs010/root/usr/bin/supervisor -e node|js|coffee -p 1000 -- server.js
[(app name).rhcloud.com (username)]\> kill 390906

That killed the process "supervisor" that re-spawns the node process. This is generally helpful, but today, it's continually incrementing the PID and it seems like that's happening more often than the gear can attempt to stop it. Unfortunately, now I can't restart it (rerunning that command in the ps output just gave me an error complaining about an Unhandled 'error' event in the supervisor script, so I decided to start the node service myself.

There are a few ways of doing this. You can go to your code and run 'node' or you can use gear start. But if you try gear start, well, it won't start if it thinks it's already running. After killing supervisor, the node process was not attempting to restart, but gear start didn't work either. I tried tricking it by clearing out the $OPENSHIFT_NODEJS_PID_DIR/cartridge.pid file, but that didn't work either... It did point out something I could use though.

[(appname).rhcloud.com (username)]\> gear stop
Stopping gear...
Stopping NodeJS cartridge
usage: kill [ -s signal | -p ] [ -a ] pid ...
       kill -l [ signal ]
Stopping MongoDB cartridge
[(appname).rhcloud.com (username]\> gear start
Starting gear...
Starting MongoDB cartridge
Starting NodeJS cartridge
Application 'deploy' failed to start
An error occurred executing 'gear start' (exit code: 1)
Error message: Failed to execute: 'control start' for /var/lib/openshift/(username)/nodejs

For more details about the problem, try running the command again with the '--trace' option.

What I found interesting about that was that it apparently tried to pass the empty pid that was in the $OPENSHIFT_NODEJS_PID_DIR/cartridge.pid file along to kill and kill didn't know what to do with that. In fact, kill returns a failed error code if you don't tell it what to kill OR if you tell it to kill something that wasn't there (original issue), so instead of getting an 'okay' back from the kill command when the gear script tried to run it, it got a failure and that meant problems for gear. So, I thought if I got something running on a PID that it COULD kill and put that PID in the file, it'd kill it successfully and everything would be back to normal. Easiest thing I could think of was to stick the '}' in my script that I'd forgotten and run that.

The node code is stored in /app-deloyments/<datestamp>/repo/ .. but don't expect things you put here to stick around.

\> node server.js 
^Z
\> ps aux
USER        PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
1313     240483  0.0  0.0 105068  3152 ?        S    17:02   0:00 sshd: (user)@pts/1
1313     240486  0.0  0.0 108608  2124 pts/1    Ss   17:02   0:00 /bin/bash --init-file /usr/bin/rhcsh -i
1313     275483  0.3  0.4 467788 36892 ?        Sl   17:24   0:01 /usr/bin/mongod --auth -f /var/lib/openshift/(user)/mongodb//conf/mongodb.conf run
1313     284292  2.5  0.6 732440 45924 pts/1    Sl   17:30   0:02 node server.js
1313     287036  2.0  0.0 110240  1156 pts/1    R+   17:32   0:00 ps aux
\> echo "284292" > $OPENSHIFT_NODEJS_PID_DIR/cartridge.pid

So, PID is in the file, and the PID is a valid running node process. Then I did my git commit of my fix, and ran git push... and it was back to normal!

Counting objects: 5, done.
Delta compression using up to 8 threads.
Compressing objects: 100% (3/3), done.
Writing objects: 100% (3/3), 344 bytes | 0 bytes/s, done.
Total 3 (delta 2), reused 0 (delta 0)
remote: Stopping NodeJS cartridge
remote: Stopping MongoDB cartridge
remote: Saving away previously installed Node modules
remote: Building git ref 'master', commit f5e40ef
remote: Building NodeJS cartridge
remote: npm info it worked if it ends with ok
...
remote: npm info ok 
remote: Preparing build for deployment
remote: Deployment id is aa38fed5
remote: Activating deployment
remote: Starting MongoDB cartridge
remote: Starting NodeJS cartridge
remote: Result: success
remote: Activation status: success
remote: Deployment completed with status: success

So, now that the PID was stable and correct, it seemed to deploy properly and I've had no troubles since!

OpenShift Solving the: 'PID Does not match' Error

OpenShift is a great free service (and paid for larger requirements) to run your Java, Node.JS, Ruby, Python and Perl apps in the cloud quickly and easily. Basically, for the un-initiated, it works like this:

• Sign Up
• Get assigned a git repo
• Clone the repo locally
• Put code in the repo
• git commit and then git push

Upon pushing the code up, it will execute your server (Sometimes you'll need to write a small config file to tell it What to run) and you're done. I'm using it for Node.js along with what they call a cartridge for MongoDB. Just purring right along until yesterday, when I get this error during a git push:

remote: Stopping NodeJS cartridge
remote: Warning: Application '(appname)' nodejs PID (322361) does not match '$OPENSHIFT_NODEJS_PID_DIR/cartridge.pid' (14154
remote: 390925).  Use force-stop to kill.
remote: An error occurred executing 'gear prereceive' (exit code: 141)
remote: Error message: Failed to execute: 'control stop' for /var/lib/openshift/(username)/nodejs
remote: 
remote: For more details about the problem, try running the command again with the '--trace' option.
To ssh://(username)@(app name).rhcloud.com/~/git/(app name).git/
 ! [remote rejected] master -> master (pre-receive hook declined)
error: failed to push some refs to 'ssh://(username)@(app name).rhcloud.com/~/git/(app name).git/'

Well, that's annoying. I did find that I can connect in and manually restart the app by killing the running node pid (ps aux lists it, and then kill (pid) to kill it.) Because they're running 'supervisor' it'll respawn the node process. However, it didn't actually seem to get my git push either. So, I'm now re-running the old code. Not very handy. Of course, there's no way I can git push 'force-stop' and it actually be valid, so I'm left wondering what I can do to get back up and developing.

Turns out, it's not that hard to fix. Observe:

# ssh (username)@(app name).rhcloud.com
(app name) (username)]> ps aux
USER        PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
1313     315834  0.3  0.4 471888 34752 ?        Sl   21:51   0:02 /usr/bin/mongod --auth -f /var/lib/openshift/(username)/mongodb//conf/mongodb.
1313     319791  0.0  0.0 104916  3120 ?        S    21:52   0:00 sshd: (username)@pts/0
1313     319809  0.0  0.0 108608  2064 pts/0    Ss   21:52   0:00 /bin/bash --init-file /usr/bin/rhcsh -i
1313     322361  0.6  0.7 733380 57516 ?        Sl   21:53   0:03 node server.js
1313     360061  2.0  0.0 110240  1148 pts/0    R+   22:02   0:00 ps aux
1313     390906  8.1  0.1 1021104 9008 ?        Sl   Dec10 226:34 node /opt/rh/nodejs010/root/usr/bin/supervisor -e node|js|coffee -p 1000 -- server.js
(app name) (username)]> vi $OPENSHIFT_NODEJS_PID_DIR/cartridge.pid

Now, that will open up vi with the pid file in it. Your PID's might vary, but you're going to want to delete whatever is in this file, and put the pid of the node process (in bold above). In my case here, it was 322361. Once I put that in there and saved it (ESC :wq <= For you non-vi types), you should be back in business. Run another git push and you should be back to your normal git output, something along these lines:

Counting objects: 8, done.
Delta compression using up to 4 threads.
Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 679 bytes | 0 bytes/s, done.
Total 6 (delta 4), reused 0 (delta 0)
remote: Stopping NodeJS cartridge
remote: Stopping MongoDB cartridge
remote: Saving away previously installed Node modules
remote: Building git ref 'master', commit f9d21d1
remote: Building NodeJS cartridge
remote: npm info it worked if it ends with ok
remote: npm info using npm@1.2.17
remote: npm info using node@v0.10.5
...
remote: npm info ok 
remote: Preparing build for deployment
remote: Deployment id is a878ff76
remote: Activating deployment
remote: Starting MongoDB cartridge
remote: Starting NodeJS cartridge
remote: Result: success
remote: Activation status: success
remote: Deployment completed with status: success