Monday, March 11, 2019

ts: epitome of the Unix philosophy

Do one thing and do it well - the Unix philosophy

In this new age of Linux bloatware (hello, systemd), it is exhilarating to discover small gems like ts, a command-line tool that prepends a timestamp to each output line.

How is this useful?

I run scripts all the time—bash scripts, Ansible playbooks, etc–to automate system administration tasks. Many longer-running scripts that I run output statements in real-time to report what they are doing. For example, running an Ansible playbook will automatically output the name of the individual task as it is being executed. By default, however, no timestamps are displayed for the tasks.

$ ansible-playbook -b -i hostsfile myPlaybook.yml
PLAY [localhost] ****************************************************************

TASK [Gathering Facts] **********************************************************
ok: [localhost]

TASK [Disabe Caps Lock] *********************************************************
ok: [localhost]

TASK [Install X apps] ***********************************************************
ok: [localhost] => (item=autokey-gtk)
ok: [localhost] => (item=gnucash)

TASK [Install 64-bit texamker - Debian] *****************************************
changed: [localhost]
PLAY RECAP **********************************************************************
localhost : ok=8 changed=2 unreachable=0 failed=0

Often, I do want to display the timestamps for logging or troubleshooting purposes. An unusually short (or long) execution may signal something is amiss.

Granted, you can use the Ansible-specific profile_tasks plugin to profile your tasks. But, I propose ts as a quick-and-dirty solution: just pipe Ansible output to ts like the following.

$ ansible-playbook -b -i hostsfile myPlaybook.yml |ts
Mar 11 11:44:05 PLAY [localhost] ****************************************************************
Mar 11 11:44:05
Mar 11 11:44:05 TASK [Gathering Facts] **********************************************************
Mar 11 11:44:05 ok: [localhost]
Mar 11 11:44:06
Mar 11 11:44:06 TASK [Disable Caps Lock] *********************************************************
Mar 11 11:44:06 ok: [localhost]
Mar 11 11:44:06
Mar 11 11:44:06 TASK [Install X apps] ***********************************************************
Mar 11 11:44:10 changed: [localhost] => (item=autokey-gtk)
Mar 11 11:44:14 changed: [localhost] => (item=gnucash)
Mar 11 11:44:14
Mar 11 11:44:14 TASK [Install 64-bit texamker - Debian] *****************************************
Mar 11 11:44:19 changed: [localhost]
Mar 11 11:44:30 PLAY RECAP **********************************************************************
Mar 11 11:44:30 localhost : ok=8 changed=3 unreachable=0 failed=0

Optional ts arguments

By default, the ts command inserts the absolute timestamp into each output line. You can use the -s argument to replace the absolute timestamp with the elapsed duration since the start of execution.

$ ansible-playbook -b -i hostsfile myPlaybook.yml |ts -s
00:00:01 PLAY [localhost] ****************************************************************
00:00:01 TASK [Gathering Facts] **********************************************************
00:00:01 ok: [localhost]
00:00:02 TASK [Disable Caps Lock] *********************************************************
00:00:02 ok: [localhost]
00:00:02 TASK [Install X apps] ***********************************************************
00:00:06 changed: [localhost] => (item=autokey-gtk)
00:00:10 changed: [localhost] => (item=gnucash)
00:00:10 TASK [Install 64-bit texamker - Debian] *****************************************
00:00:15 changed: [localhost]
00:00:26 PLAY RECAP **********************************************************************
00:00:26 localhost : ok=8 changed=3 unreachable=0 failed=0

Another useful argument to know is -i. With this argument, each output line displays the elapsed time since the previous output line. You don't need to do the mental math to calculate how long a task took.

$ ansible-playbook -b -i hostsfile myPlaybook.yml |ts -i
00:00:00 PLAY [localhost] ****************************************************************
00:00:00 TASK [Gathering Facts] **********************************************************
00:00:01 ok: [localhost]
00:00:00 TASK [Disable Caps Lock] *********************************************************
00:00:00 ok: [localhost]
00:00:00 TASK [Install X apps] ***********************************************************
00:00:04 changed: [localhost] => (item=autokey-gtk)
00:00:04 changed: [localhost] => (item=gnucash)
00:00:00 TASK [Install 64-bit texamker - Debian] *****************************************
00:00:05 changed: [localhost]
00:00:00 PLAY RECAP **********************************************************************
00:00:00 localhost : ok=8 changed=3 unreachable=0 failed=0

In summary, ts is a fast and easy way to add timestamps to script or command output.