Reading the Xi-Text System Log (spshed_reps)

Understanding the System Log

Xi-Text writes one file that records faults: the system log, spshed_reps. Three programs write to it - the spooler spshed, the process that drives each printer, and the program that reads a printer's setup files. Every entry is a failure, an operator-requested stop, or the spooler starting.

Two consequences follow, and both matter more than anything else in this article:

• Silence means health. A working installation writes one line when the spooler starts and nothing else until something goes wrong. Xi-Text says so itself: press X in spq on a healthy system and the message reads "There is nothing in the system error log file (for this machine) to view. Nothing is wrong - don't worry!"
• This is a fault log, not an activity log. Print jobs, job selection, printers starting and stopping, printers going offline and successful configuration reads leave no trace here. Looking for them is the most common way to waste an hour on a printer problem. The full list is under "What Is Never Recorded" below.

Location:

/var/spool/xi/spd/spshed_reps

The directory is the spool directory. If your installation has been relocated, read the real value from the SPOOLDIR setting in the master configuration file /etc/xi/textconfig; a build blend can move it too.

Ownership and permissions:

The file is created by whichever process first has something to report, and the daemons narrow their umask before they write, so the mode is 0600 and the owner is the spooler account. Nothing in the packages creates it in advance, and nothing ever changes its mode afterwards.

That has a practical consequence worth knowing before you try: an ordinary user cannot read this file directly. To use cat, tail or grep on it you must be root or the spooler account:

su spooler -c "tail -50 /var/spool/xi/spd/spshed_reps"

Any user can read it through spq's X key, because spq is installed set-user-id to spooler. For an operator, that is the route.

What Gets Logged

Spooler start and stop

These are the only entries a healthy system produces, and the first two are the only ones seen in normal operation:

spshed started.
spshed stopped normally.
spshed stopped - killed
spshed stopped due to program fault (coredump)
spshed stopped due to program fault (coredump) in net monitor
spshed stopped due to licence expiry.

The first is written as the spooler enters its main loop. The second is written when sstop asks it to stop. The third is written when the spooler receives a termination signal, which is what a systemd stop does. The fourth and fifth are written when the spooler or its network monitor dies on a bus error, an illegal instruction or a system-call fault, and the last when the licence has run out.

Anything else from spshed means the spooler has just exited

This is the single most useful rule the file offers. Almost every other message the spooler writes is fatal: it writes the message and exits immediately. So an entry naming spshed that is not one of the lifecycle messages above almost always tells you the spooler stopped at that moment, and the printers stopped with it. The messages concern shared memory, the request socket, the lock files, the saved job and printer files, and malformed internal messages. Three examples in their real wording:

Could not create job save file - No space left on device
Trouble creating shared memory id 58691004 - File exists
Possibly some other software is using it all up, or the maximum shared
memory size allocated in your kernel is too small.
If the message given above is "File Exists" try removing files with names
starting "spmm_" from the spool directory.
Cannot create message socket - Address already in use
Is it possible that the previous shutdown was not clean?

Those are three separate entries, shown without their headers. The second is an example of a message that runs to several lines and carries its own advice - a shape worth expecting, because a one-line tail will cut it in half.

Setup-file faults

When a printer starts, its setup files are read by a separate program, and every diagnostic that program produces lands here. These are the entries that name a file and a line number:

Error near line 12 - probable undefined name `netwrk'.
Error near line 8 - Number expected
Error near line 20 - Expected a `}'
Error near line 3 - Invalid baud rate 19201
Error near line 5 - Identifier too long
Error near line 7 - Unterminated regular expression

Two further messages appear when no setup file can be found at all - one saying there is no directory for the printer in the printers directory, one saying there is no setup file (not even a default) in it. Both run to several lines and name the printer and the directory.

Device and printing faults

These come from the process driving the printer. The name in each is the printer's device, which is the closest these entries come to identifying the printer:

Open of /dev/lp0 gave error - Permission denied
Invalid device name /tmp/printout
Error on output - Input/output error
Cannot run banner program `/usr/local/bin/mybanner'
Banner program `/usr/local/bin/mybanner' terminated with exit 1
Network printer ptr9 (addr/dev srv:9100) does not have network command specified or non-network printer does

Network transport faults

A printer reached over the network is driven by a transport command, and its failures are recorded:

Network filter process (/usr/libexec/xi/xtelnet -p 9100 -h srv) terminated with exit code 1
Network filter process (/usr/libexec/xi/xtelnet -p 9100 -h srv) terminated with signal 13
Network filter process (/usr/libexec/xi/xtelnet -p 9100 -h srv) pid 4711 apparently hung
Seem to have lost track of network filter process (/usr/libexec/xi/xtelnet -p 9100 -h srv) id 4711 - No child processes

If the printer's setup file carries the logerror keyword - which the shipped network device defaults do - each line the transport writes to its standard error is copied here as a pair of entries:

Error report from printer ptr9 on device srv:9100
Report was: connection refused

That pair is the only entry in the file that names the printer it came from. See "The entry does not name the printer" below.

Networking between Xi-Text hosts

Failures only - a probe socket that could not be created or bound, a truncated or unrecognised message from a peer, a reconnection attempt to a host already connected, and errors found while reading the hosts file. A connection being made or lost is recorded nowhere.

What Is Never Recorded

An article about using this log is defined as much by what is absent as by what is present. None of the following ever reaches spshed_reps:

• Jobs. No submission, no selection, no start, no completion, no abort, no deletion. The routine that gives a job to a printer contains no reporting call of any kind, so a job that matches no printer waits for ever and writes nothing. See article 26.
• Printers going offline. All four routes into the offline state write the state and nothing else. A printer that has been switched off, has run out of paper or has lost its cable leaves no entry. See article 25.
• Printers starting, stopping, halting or finishing a job. There is no message for a state change as such - only for the failures that cause some of them.
• A successful setup-file read. The setup-file reader has no success path; a clean read writes nothing. See article 16.
• A printer whose process died untidily. The spooler notices and sets the state to error, and that assignment writes no message. An error with nothing in the log is the sign of this case rather than of a broken log.
• Privilege refusals. Every privilege test is applied by the command the user ran, which prints its own message and exits.
• The master configuration file. If /etc/xi/textconfig is absent it is silently ignored and the compiled-in defaults are used. If it contains a syntax error, every Xi-Text program prints the error on its standard error output and exits - that message does not come here.
• The network server. xtnetserv writes nothing to this file, despite what the Administration manual says. Its own diagnostics - a port it could not open, for instance - go to its standard error, and nothing redirects that, so on a machine started at boot they are discarded. If a networked Xi-Text host will not accept remote work and the log is empty, this is why.
• Per-job accounting. That is the record and logfile keywords in a printer's setup file. Each writes its own file, by default in the printer's own directory and mode 0644. logfile gives one pipe-separated line per job - date, start and finish times, elapsed time, user, title, form type, characters, device, printer, priority, pages and job number - written as a single atomic append, so several printers may share one file safely. record is not a log at all: it is a binary running total of characters at a fixed offset in the file, so it must never be read with a text tool or rotated.

Xi-Text writes nothing to the operating system's syslog: no part of the product calls it, so nothing appears in the journal or in the system messages file. Between spshed_reps, the two per-printer files above, and the per-job error report that is mailed to the job's owner and then deleted, this file is the whole of Xi-Text's own diagnostic output. The one exception is the LPD server xtlpd, which writes its own untimestamped file if its control file names one.

Log Entry Format

An entry is a header line, a line of exactly fourteen equals signs, and the message - which may run to several lines. Entries follow one another with no blank line between them and with no terminator, so the start of the next header is what ends the previous entry. Counting entries is therefore grep -c '^==============' rather than wc -l.

Two header shapes exist. The spooler and the printer process write the time first:

10:15:22 06/02 - spshed
==============
spshed started.

The setup-file reader writes its own name, the file it was reading, and then the time:

SPDI: /var/spool/xi/printers/ptr1/a4.ps: 10:20:15 06/02
==============
Error near line 12 - probable undefined name `netwrk'.

Three properties of the header decide what you can do with the file:

• There is no year. The date is day and month only, and nothing rolls the file over, so entries from previous years sit in the same file indistinguishable from this year's. Date an entry by its position in the file rather than by its timestamp.
• The day and month are swapped in time zones four or more hours west of UTC, so a North American installation reads 02/06 where a European one reads 06/02.
• The name in the header is the program, not the printer. spshed is the spooler, spd the process driving a printer, SPDI the setup-file reader.

The entry does not name the printer

The setup-file reader's header includes the printer's directory, so its entries identify the printer. The printer process's entries carry the program name and nothing else. What identifies the printer in practice is the message text - "Open of /dev/lp0 gave error" names the device, and the network messages name the transport command line, which carries the address. On a host with several printers on similar devices, correlate the entry with splist output rather than assuming.

Accessing the Log File

Method 1: Direct file access

As root, or as the spooler account:

# View the whole log
cat /var/spool/xi/spd/spshed_reps

# View the most recent entries
tail -50 /var/spool/xi/spd/spshed_reps

# Watch entries as they are written
tail -f /var/spool/xi/spd/spshed_reps

# Find the entries for one device
grep -n /dev/lp0 /var/spool/xi/spd/spshed_reps

# Count the entries
grep -c '^==============' /var/spool/xi/spd/spshed_reps

All of these work unchanged on every platform Xi-Text ships on: the file is plain text, line-oriented and seven-bit, so the vendor grep, tail and awk on Solaris, AIX and HP-UX handle it. Filtering is rarely worth doing, because everything in the file is a fault, so tail usually answers the question. A message may span several lines, so a grep match arrives without its header - that is why -n is used above, so the surrounding lines can be read.

Method 2: The X key in spq

X opens the log from any spq screen - the job screen and the printer screen alike - so there is no need to switch screens first. The heading reads "System error log file".

In the viewer:

• Cursor keys move through the file, Space shows the next screenful
• L and R scroll left and right, < and > jump to the left and right margins
• B and E jump to the beginning and the end of the file
• ^ and \ search forwards and backwards
• q returns to the screen you came from

If the file does not exist yet, spq says so and stays where it is. This is the only route to the log for an operator with no shell access to the spool directory, and it needs no privilege beyond reaching an spq screen.

Method 3: spstart shows it when the spooler will not start

If spstart starts the spooler and still cannot reach it afterwards, it prints the last eight lines of spshed_reps on its standard error before exiting. This is the one place the log comes to you rather than the other way round, and it is worth recognising: those eight lines are the reason the spooler failed.

Clearing the log from the X11 clients

Both graphical clients offer a "clear the log" action alongside the viewer, and the two behave differently. The GTK client truncates the file, which is safe. The Motif client deletes it. The spooler and every running printer process hold the file open, so after a Motif clear they carry on writing into a file that no longer has a name: every entry they produce between then and the next spooler restart is lost, while entries from the setup-file reader continue to appear in a new file. If your site uses the Motif client, treat that button as unavailable.

Using the Log for Troubleshooting

A printer will not start

This is what the log is for. spstart reports success whether or not the printer starts, because the spooler starts the printer in a separate process, so the log is the only place the reason appears.

splist ptr1
su spooler -c "tail -20 /var/spool/xi/spd/spshed_reps"

Expect one of: a setup-file parse error naming the file and the line; a message that there is no printer directory or no setup file; "Open of <device> gave error"; "Invalid device name"; or the network-command message. Article 24 maps each of these to its cause and its fix.

If splist shows error and the log holds nothing at all, the printer's process died rather than reported - again, article 24.

Jobs are not printing

The log has nothing to offer here, which is worth stating plainly because it is where readers look first. Job selection is never recorded. Work from sqlist and splist instead, following article 26.

A printer keeps stopping

If the state is error, the log carries the reason. If the state is offline, it carries nothing - diagnose from the printer itself, following article 25. For a network printer, the logerror keyword in its setup files brings the transport's own complaints into the log, which is usually decisive.

The spooler stopped by itself

Read the end of the file. An spshed entry other than the four start and stop messages is the cause, and the spooler exited at the moment it was written.

Managing the File

The file has no size limit, and nothing in Xi-Text rotates, truncates or reopens it. On a healthy system it grows by one entry each time the spooler is started and needs no attention for years. It grows quickly only when something is failing repeatedly - a flapping network printer with logerror set is the usual case - and that is a fault to fix rather than a file to manage.

Rotate by copying and truncating, never by renaming

The spooler and each printer process open the file once and hold it open for their whole lifetime. No signal makes them reopen it - the spooler ignores SIGHUP outright, and the printer process uses it for something else - so the only way to make them let go of the file is to stop the spooler. Renaming the file and creating a new one, which is what the ordinary rotation tools do by default, leaves the spooler and the printers appending to the renamed or deleted file for ever, with no message and no way to notice except that the new file stays empty. The setup-file reader opens the file afresh each time, so after a mishandled rotation its entries continue to appear in the new file while the spooler's and the printers' entries vanish - which reads as a partial log rather than a broken one.

Copying and truncating is safe, because the file is opened in append mode:

#!/bin/sh
# rotate-xitext-log.sh - run from cron, monthly

LOG=/var/spool/xi/spd/spshed_reps
STAMP=`date +%Y%m%d`

if [ -f "$LOG" ]
then
    cp "$LOG" "$LOG.$STAMP"
    : > "$LOG"
fi

# Add to the spooler account's crontab
0 2 1 * * /usr/local/sbin/rotate-xitext-log.sh

Deleting old copies is a local decision; write it with whatever your platform's find supports, since the -delete option and the handling of -mtime differ between Solaris, AIX, HP-UX and Linux.

On Linux, logrotate can be used provided it is told to copy and truncate. Its default rename-and-create behaviour breaks the log:

# /etc/logrotate.d/xitext
/var/spool/xi/spd/spshed_reps {
    monthly
    rotate 12
    compress
    missingok
    notifempty
    copytruncate
}

The copytruncate line is the whole point of that file. Leave out any create line: with copytruncate the original file survives, so its owner and mode are preserved.

Monitoring the Log

Because the file is silent on a healthy system, monitoring it is simple: anything new is worth a look. There is no need to filter for the word "error", and filtering is actively unhelpful, because most of the real messages do not contain it. Run the monitor as the spooler account or as root - the file's mode of 0600 rules out an unprivileged monitoring agent.

#!/bin/sh
# monitor-xitext-log.sh - alert on anything new

LOG=/var/spool/xi/spd/spshed_reps
STATE=/var/tmp/spshed_reps.size

[ -f "$LOG" ] || exit 0
NOW=`wc -c < "$LOG"`
[ -f "$STATE" ] || echo 0 > "$STATE"
WAS=`cat "$STATE"`

if [ "$NOW" -gt "$WAS" ]
then
    tail -c `expr "$NOW" - "$WAS"` "$LOG" |
        mail -s "Xi-Text system log activity" admin@example.com
fi
echo "$NOW" > "$STATE"

Sending the alert uses mail -s, which is the Linux and AIX spelling. Solaris and HP-UX put the subject option on mailx instead, so substitute that there - a wrong mailer here fails quietly, which is the one thing a monitor must not do.

Watching the file complements watching the printers rather than replacing it. A printer going offline writes nothing here, so a monitoring script that reads only the log misses the most common printer fault; poll splist -F "%p %t" for that, as article 25 describes.

Best Practices

Read it when something is wrong, rather than on a schedule:

A weekly review of a file that is normally empty finds nothing. Read the end of it whenever a printer will not start, a printer is in error, or the spooler has stopped unexpectedly.

Send the last few entries to support:

The Administration manual asks for exactly this, and it is the right thing to send: the last fifty lines of this file, together with the output of splist, answers most of the first round of questions.

Keep logerror on for network printers:

It is already in the shipped network defaults. It is what turns an unexplained error on a network printer into a message you can act on.

Rotate only when there is a reason to:

Growth means recurring failure. If the file is large, find out what is writing to it before deciding how often to rotate it.

Know what it leaves out:

Jobs, job selection, offline printers and successful configuration reads are elsewhere or nowhere. Sending someone to this file for those is the most common wrong turn in Xi-Text troubleshooting.