Keep it running

INPUT · Slides

Keeping a record

01 / 08

The weakness of not knowing afterwards

Last lesson you built something you could take your hands off.

0 5 * * * /home/learner/checkup.sh

But what happened at five in the morning, you did not see.

did it go well?did it fail?did it run at all?

None of it is known. All cron leaves is that it ran it.

Last lesson you got round it by writing this.

... >> /home/learner/result.log 2>&1

That does keep a record. But three things are awkward.

1. files multiply (one per job)2. no time goes in (you do not know when)3. you cannot read it beside the other records

The third matters. Inside the machine, all sorts of things are writing records.

syslogd   that it startedcrond     that it ran a jobsu        who became the administrator

And all of it is in one place, in order of time.

~ $ tail -3 /var/log/messagesAug 22 07:18 ... syslogd started: BusyBox v1.37.0Aug 22 07:19 ... crond: USER learner pid 88 cmd ...Aug 22 07:19 ... su: + ttyS0 root:learner

Your records can be mixed in here too. The tool for it is logger.

What is good about mixing them in? This.

07:19:00  crond     started the job07:19:00  checkup   five files07:19:01  checkup   odd! it was empty

It reads as a story. Scattered across separate files, you would have to line up the times by hand.

02 / 08

The shape of logger

It is very easy to use.

~ $ logger "how do you do"

That is all. Nothing appears on the screen, but it is written into the record.

~ $ tail -1 /var/log/messagesAug 22 07:19:06 fulfledge user.notice learner: how do you do

There it is. Three marks are available.

MarkWhat it doesDefault
-t tagthe name of who wrote ityour user name
-p levelhow importantuser.notice
-sshow on the screen (standard error) tooit does not

You almost always add -t.

logger -t checkup "finished"

Because of narrowing down later.

grep "checkup:" /var/log/messages

Only your job's records come out. Without a tag it is buried among the others.

It reads from standard input too.

~ $ ls /bin | wc -l | logger -t count

A command's result recorded as it is. The pipe of chapter 4 works here as well.

-s is handy while trying by hand.

~ $ logger -s -t trial "is this right?"trial: is this right?

It appears on the screen too, so you can see that it is being written. What appears goes to standard error, though, so take it with 2> (chapter 4).

03 / 08

Reading a line of the record

Let us take a written line apart.

Aug 22 07:19:06 fulfledge user.notice checkup: finished+------+------+ +---+--+ +----+---+ +--+--+ +--+--+     time       machine     level      tag    the words

Five parts.

PlaceWhatWho wrote it
timewhensyslogd puts it on
machine namewhich machinesyslogd puts it on
levelhow importantnamed with -p
tagwhose recordnamed with -t
the wordswhat happenedyou write it

You write only the last three, and the time and machine name come along by themselves. That is the big difference from writing to your own file with >>.

echo "finished" >> mine.log        no time goes inlogger -t checkup "finished"       the time goes in

Knowing when matters a great deal. You can look into "what happened last Tuesday".

To pull out a field, the tools of chapter 5 work.

~ $ awk '{print $5}' line.loguser.notice

One caution here. Do not use cut -d' '.

Aug 22 07:19:06 ...     a two-figure day -> one spaceAug  2 07:19:06 ...     a one-figure day -> two spaces!

The number of spaces changes with the day. cut counts one space at a time, so it slips. awk sees any run of spaces as one divider, so you use that. "awk stands up to spaces better", from chapter 5, comes alive here.

04 / 08

Level (facility and level)

The "level" you write after -p is two words joined by a ..

user.notice+--+ +--+-+kind  level

The front is which area it is about (facility), the back how important (level).

The areas include these.

user      what a person ran (this is you)daemon    something that runs all the timeauth      logging in and permissionscron      the one that runs things on timesyslog    the record-keeper itself

You saw them in the record just now.

syslog.info   syslogd started ...cron.info     crond: USER learner ...auth.notice   su: + ttyS0 root:learner

Which area it is about, at a glance.

There are eight levels. Heavier at the top.

levelMeaning
emergthe machine is unusable
alertneeds attention at once
critserious
erran error
warningtake care
noticea notice (the default)
infoan ordinary report
debugfine detail for looking into

You need remember only three.

err        bad (a person needs to look)warning    of concerninfo       an ordinary report

Why levels? Because you can narrow down later.

grep "user.err" /var/log/messages

Only the bad things come out. However many thousand lines, you see just the errors.

So the manner is this.

> Do not write everything as err

If everything is err, narrowing means nothing. Nobody listens to the one who cries wolf every time. Only when it is really bad, err.

05 / 08

Where the record lives

The one who gathers and writes the records is already running too.

~ $ ps -o pid,args | grep syslogd   52 /sbin/syslogd -n

A daemon, like crond (as in the last lesson).

The flow goes like this.

logger -t checkup "finished"  | hand it to the record-keepersyslogd  | put the time and machine name onadd a line to /var/log/messages

The important part is that logger does not write the file itself. It only hands it over.

Why? So that the keeper can decide where it goes.

want to change the place       -> change syslogd's settingswant to send it to another machine -> change syslogd's settingsthe writer (logger) changes nothing

On a real site the records of dozens of machines are sometimes gathered in one place. The writing side stays the same.

The places in this environment.

/var/log/messages    what syslogd writes (logger too)dmesg                the kernel's record (a separate place)

dmesg is what the kernel (the middle of Linux) wrote, kept apart from syslog. What happened as the machine woke, and hardware talk. It is read with a command rather than as a file.

~ $ dmesg | head -5

The tools for reading records.

tail -20 /var/log/messages        what happened latelytail -f /var/log/messages         watch them come in (Ctrl-C to stop)grep "checkup:" /var/log/messages just yoursgrep "user.err" ...               just the bad ones

The tools of chapters 2 and 3 work as they are. A record is only text.

06 / 08

What to record

The tool was easy. The hard part is what to write.

Write too much and it goes like this.

07:19:01 checkup: starting07:19:01 checkup: opened the file07:19:01 checkup: read line 107:19:01 checkup: read line 2... (a hundred thousand lines)

Unreadable. Too many records and it is the same as having none.

Too few and it goes like this.

07:19:01 checkup: failed

You do not know what failed.

Three guides for getting it about right.

1. Write the edges (the start and the end)

logger -t checkup "started"...logger -t checkup "finished"

With both, you know whether it ran or stopped partway. No ending means it died on the way.

2. Write numbers

logger -t checkup "files: 5"

"Five" is more use than "it went well". If it is usually five, you notice the day it is nought.

3. Bad things as err, with the reason

logger -t checkup -p user.err "no settings: /etc/checkup.conf"

Write what is missing. The one who reads it later is usually yourself, having forgotten.

One thing not to write.

> Do not put passwords or secrets in a record

Records are hard to unwrite, and other people can sometimes read them. Once it slips in, you cannot take it back.

07 / 08

Joining it to cron

Joined to the last lesson, it goes like this.

#!/bin/shset -eulogger -t checkup "started"COUNT=$(ls /home/learner | wc -l)if [ "$COUNT" -gt 0 ]; then  logger -t checkup "files: $COUNT"else  logger -t checkup -p user.err "it was empty!"fi

Hand that to cron.

0 5 * * * /home/learner/checkup.sh

And in the morning you can read it back.

~ $ grep "checkup:" /var/log/messagesAug 22 05:00:00 ... checkup: startedAug 22 05:00:00 ... checkup: files: 5

What happened while you slept, left in words. That is what the last lesson lacked.

There is a one-line way too, written straight into the table.

0 5 * * * /home/learner/checkup.sh || /usr/bin/logger -t checkup -p user.err "failed"

The || is from chapter 11. Record only on a failure. Its value is that you can add it later without touching the script.

A guide to choosing.

want the goings-on inside   -> write logger in the scriptwant only success or failure -> || logger in the table

Both is fine too.

And get into the habit of reading records.

grep "user.err" /var/log/messages

Just the bad things, now and then. That alone prevents "it had been broken for three months and nobody noticed". Writing records is not the point; they only earn their keep once read.

08 / 08

Now have a go

Here are the shapes for this lesson.

logger "words"                     add a line to the recordlogger -t tag "words"              give it a name (nearly always)logger -t tag -p user.err "..."    change the levellogger -s -t tag "..."             show it too (take with 2>)command | logger -t tag            record a result as it is

And for reading.

tail -20 /var/log/messages        what happened latelygrep "tag:" /var/log/messages     your recordsgrep "user.err" ...               just the bad onesawk '{print $5}' ...              pull out a field (not cut)dmesg                             the kernel's record

Three things to remember most today.

1. put a tag on with -t (to narrow down later)2. do not make everything err (narrowing loses its point)3. the time comes on by itself (you need not write it)

And today's conclusion.

> Leave in words what happened while you were not watching

Last lesson you learned to take your hands off. Today you made what happened in that time readable afterwards. Only with both can you hand things over in peace.

This lesson has one exercise that waits a minute, the last one.

From the next lesson it is networking. You check your own address with ip, try whether it reaches with ping, and end by standing up a web server of your own. Let us type.