How to tail a log with live server clock

At work I have to watch my server’s error log. Good old tail -F /path/to/log runs over SSH all day, every day. Each entry is timestamped. Sometimes those timestamps give me trouble. The age of a timestamp is found by subtracting it from the current time. If I need to know whether the last error occurred 1 minute ago or 61 minutes ago I have to contend with:

  • timestamps in UTC vs. local clock in CST
  • timestamps in 24h vs. local clock in 12h
  • terminal window on second screen vs. clock on main screen
  • daylight savings vs. non-crazy time
  • being at home vs. traveling in other time zones

Finding the age of a timestamp should be simpler than that! So I put a real-time UTC clock in the most convenient place I could find: on the blank line where the next log entry will be written. It refreshes itself every second. Log entries overwrite it and then it reappears again on the new blank line.

The clock on the next line refreshes itself.
The clock on the next line refreshes itself.

Now I can find the age of the last entry without thinking about time zones or daylight savings, without turning my head to check the clock, and without even holding any numbers in my head. Eyeball math. Success!

#!/bin/bash
ssh $1 $(cat <<COMMAND
    while true; do
        echo -ne \`date +"[%d-%b-%Y %H:%M:%S UTC]"\` "\r";
        sleep 1;
    done &
    tail -Fn`tput lines` $2
COMMAND)
echo

If you save this script as st in your path and chmod +x it you can invoke it with st example.com /var/log/file (provided you can ssh example.com and read the file).

I used a few small tricks to compose this solution.

  • the while loop runs in the background (done &)
  • echo -n prints its arguments without a line feed
  • echo -e interprets escape sequences, converting "\r" into a carriage return
  • bonus: `tput lines` passes the local terminal height to tail
  • the final echo gives your prompt a fresh line when you exit with ^C

After SSH connects, the loop starts sending [timestamp]\r to the terminal every second. The carriage return moves the insertion point back to the start of the line without moving it down to the next line. That explains the location of the highlighted character in the image above.

Then tail fills your terminal window with log entries and continues printing new entries as they appear, overwriting the clock. No space wasted, no information lost.

Caveats:

  • log entries must be timestamped and must end in a newline
  • date format is up to you
  • n`tput lines` is optional
  • the clock might draw over log data

That last point is theoretical. It hasn’t been an issue in the two months since I started using this. I also tried to force the clock to overwrite the tail output under abnormal conditions. The only way I could do it was by manually appending to the file without a trailing newline. I guess it depends on the size of the log entries and how they are written. Either way, it’s only terminal output. The log file itself is unmodified.

The script I posted above isn’t exactly what I have been using. It was modified for clarity and generality. I added positional parameters and $(cat <<heredoc) to get clean newlines without having to escape too much. Since I only use this utility to tail one file on one host, the original looks more like this one-liner:

ssh example.com 'while true; do echo -ne `date +"[%d-%b-%Y %H:%M:%S UTC]"`"\r"; sleep 1; done & tail -Fn'`tput lines`' /var/log/file'; echo

My SSH config setup

Ask me “What do you do?” If you don’t sound particularly interested, I’ll tell you “I type.” Ratchet up your inquisitiveness and I might tell you that I write computer programs or blogging software. Eventually you’ll find out that I spend most of my time in SSH. If you are the same way and you want to improve your SSH experience, you might like this article. (Unless you are using Windows.)

~/.ssh/config is where my SSH configuration is stored. I encourage you to `man ssh_config` and read about the options listed in this article. Also `man sshd_config` for more details.

Don’t live in the country.

Measured in latency, packet loss, and bandwidth, my home internet connection is pretty poor. That’s because I live in a valley where there is no ISP presence. There are two radio hops between me and the fiber network. That makes four radio hops per round-trip. To mitigate the effects of an unreliable physical network, I put these lines at the top of ~/.ssh/config:

# Do not kill connection if route is down temporarily.
TCPKeepAlive no

# Allow ten minutes down time before giving up the connection.
ServerAliveCountMax 30
ServerAliveInterval 20

# Conserve bandwith. (Compression is off by default.)
Compression yes

Label your windows

If I have many tabs in my log window, as I usually do, I need something better than the memory game to tell them apart. It’s possible to change the window title by echoing an escape sequence. My default remote .bashrc sets up the shell to update the window title with user, hostname, and working directory every time the prompt is displayed. This makes it easy to know where you are after switching tabs:

PROMPT_COMMAND='echo -ne "33]0;${USER}@${HOSTNAME}: ${PWD}07"'

However, my log connections have no shell prompt so they need another way to set their window titles. So before I start SSH I echo an escape sequence to update the window/tab title. This is shown in the BASH script a bit later.

A minor side-effect of setting your window title is that it remains set until you change it. Quitting SSH doesn’t reset the window title. So I added the PROMPT_COMMAND line above to my local .bashrc to bring the same dynamic title effect to my local shells.

Make complex connections simple

To give context to the next snippets, I must describe my windows. At least one terminal window is dedicated to tailing logs on remote servers while I run text editors and shells in other windows. At any given time there are usually two or more connections to one server and I like to run all of these through a single TCP socket. So I add lines like these for every host for which I always want a master connection:

Host sandbox.example.com
User sandbox
ControlMaster auto
ControlPath ~/.ssh/sandbox.example.com.sock

I also use cryptographic keys to eliminate password entry. Now when I `ssh sandbox.example.com` it automatically uses an existing master socket, or else creates a new master socket for reuse by subsequent connections. That’s very handy but beware: don’t close the master connection while you have unsaved changes in another tab! You might want to use screen. I take my chances.

After I have my master connection, I can start and stop shells in other windows. I connect to a small number of hosts and on each one I like to tail different files and forward different ports. So for each host I maintain a little script to help me manage the connections. Here is a sample script that starts the log connection on first invocation and shell connections subsequently:

#!/bin/bash
#/usr/local/bin/sandbox
ssh -O check sandbox.example.com
if [ "$?" == "0" ]; then
    # master already running
    ssh sandbox.example.com
else
    # change window title, start the master, and tail some logs
    echo -ne "33]0;sandbox.example.com logs07"
    ssh sandbox.example.com -D 8080 tail -F error.log debug.log
fi

This lets me set up my environment very quickly: I run sandbox in the log window to start the master, then I run the same command in any number of other windows to start shells. The commands are short and easy to remember. The startup time for shells is now much faster because the connection is already negotiated. My log windows are labeled. What else could I want?

I usually come up with tiny nicknames for my most used connections and place these in /etc/hosts with the IP of the host. This saves typing time as well as time waiting for DNS round-trips.

The only remaining annoyance is the inevitable disconnection with unsaved changes. Maybe later I’ll learn to make screen work automatically and transparently so that I never lose work due to network disruption.

Detachable IRC Proxy: dircproxy

Because much of my work happens in IRC, I like to stay attached to the Freenode IRC server all the time. This was easy when I kept a desktop computer always on. But now that I use my laptop exclusively it’s impossible: every time I close the lid my IRC connection closes, so I can’t read what was said and nobody can send me a message.

So I went looking for something that could keep me online even while my laptop sleeps. I found dircproxy, a Detachable IRC Proxy that runs on Linux. It was easy to install from Aptitude in Debian but their version had one very annoying bug, so I compiled the current dircproxy source code and installed the new binary by hand. Now everything is sweet.

When I want to connect to Freenode, I actually connect to dircproxy, which in turn connects to Freenode. When I quit, dircproxy keeps my IRC nickname online and logs everything that happens while I’m away. When I return, dircproxy plays back the logs so I know who said what when, including private messages. It’s like I was never gone.

Aside from solving the basic problem of intermittent connectivity, dircproxy has other benefits. You can make it keep complete logs apart from the ones it uses internally. You can specify different nicknames for when you detach. You can customize messages to send when you detach and reattach, as well as auto-replies for when you are away. It has a long list of options I don’t understand, but they look good.

I was discouraged when I found a lot of dead links, but the project has been uploaded to Google Code and it’s getting some attention again. The Freenode dircproxy channel has 15 members. I hope they can attract more developers to the project. They also need some new links to get them past the old, dead ones. Blog it if you try it.