AIX Printer Tips: Tracing Remote Printing

About This Document

This document addresses the following question: What is getting sent to the remote system when I print?

One reported problem is that the RS/6000 is sending header pages to remote printers but the header page is actually created on the remote printer. Another problem is to determine what flags are actually passed to the printer from the backend 'rembak'.

Remote printing to an LPD is governed by RFC 1179. You should be familiar with this document if you want to do in-depth analysis of print traces.

The information in this document applies to AIX Version 3 and Version 4.x.

What an iptrace Can Tell You

What characters are actually sent to over the network, even binary control characters?
What response comes from the LPD?
What is contained in the control file?
Which side terminated the converstion?
What status information is being sent back by the LPD?
Does the entire file get sent to the lpd?
Do the control files follow the RFC 1179 standard?

How To Do a Remote Trace

The 'iptrace' facility can easily show what is being sent to the remote system using the following commands:

# iptrace -p printer -a -b -s source_host -d dest_host /tmp/trace.out

-p printer (use the word printer) or 515 says look at port 515 only. This won't get logon traffic.

-a means suppress ARP packets

-i en0 Interface. (Only use if multiple network cards are in the system.

-b means change the -d and -s to bidirectional mode. Get data in both directions.

-s source hostname or ipaddress where the print command is issued

-d destination hostname or ipaddress where the printer is

/tmp/trace.out - This can be any filename. It will be created with 11 bytes and then will get filled with data. It is a binary file that must later be formatted with ipreport

# enq -Pqueue_name filename

lpstat -vqueue_name

# ls -l /tmp/trace.out

# ps -ef | grep ipt

# kill -9 job_id

# ipreport /tmp/trace.out > /tmp/report.out

The report contains three or four parts for each packet of data. These are:

MAC header
IP header
TCP header
b>data (If to/from application layer; i.e. if FLAG=PUSH)

How To Interpret the Trace

The MAC header doesn't supply much information usefull to debugging printing.

The IP header gives us the direction of the data flow, and the number of bytes in the packed, but direction is also given in the TCP packet.

The TCP packet gives us the following:

direction of packet source port..destination port

handshaking and purpose of packet flags

source port number

packet identification.

window size th_win

The data packets contain queue names, command information, actual data to be printed, print flags, and also error messages back from the remote system lpd. It often simplifies the reading of the data to extract the data from the other packets. This is usually quite easy to do because all data lines of importance begin with at least 4 zero's. However when you do this, you destroy the information about who sent individual packets.

# grep 0000 /tmp/report.out > /tmp/datasent.out

The size of this file will greatly depend on the size of the data file being printed. For this reason, starting with a small file helps when testing. A useful command is:

$ echo "AAAAA" | qprt -Pqueue_name

This will show in the grep output as:

...
00000000     41414141 410a                           |AAAAA.          |
...

Notice that the data is divided into three columns. These are:

Column 1, This is a character count, prior to the current line.
Column 2, This is the data in HEX.
Column 3, This is the data in ASCII, with periods for non-printable characters.

A PostScript output might look something like this:

!data        hex equivalent of the characters         ASCII equiv. of
!byte in     sent to the remote host                  the characters.
!packet
00000000     020405ac                                |....            |
00000000     020405ac                                |....            |
00000000     0268705f 706f7374 0a                    |.hp_post.       |
00000000     00                                      |.               |
00000000     03363433 36382064 66413132 30746573     |.64368 dfA120tes|
00000010     63680a                                  |ch.             |
00000000     00                                      |.               |
00000000     04252150 532d4164 6f62652d 332e300d     |.%!PS-Adobe-3.0.|
00000010     0a252543 72656174 6f723a20 57696e64     |.%%Creator: Wind|
00000020     6f777320 50534352 4950540d 0a252554     |ows PSCRIPT..%%T|
00000030     69746c65 3a20524f 444e4559 322e574b     |itle: RODNEY2.WK|
00000040     330d0a25 25426f75 6e64696e 67426f78     |3..%%BoundingBox|
00000050     3a203138 20392035 39332037 38340d0a     |: 18 9 593 784..|
00000060     2525446f 63756d65 6e744e65 65646564     |%%DocumentNeeded|
00000070     5265736f 75726365 733a2028 6174656e     |Resources: (aten|
...

Information gained from this output

'hp_post' was the remote queue name.
The data file contains 64368 bytes.
The job number is 120.
'tesch' was the local host name.
Obviously this is a postscript file %!PS-Adobe-3.0.

Some of the things to look for in the output are:

There is always an initial handshake protocol that seems to look like:

00000000     020405ac                                |....
00000000     020405ac                                |....

The middle column always starts 02 for the handshake part. The rest is identification information and doesn't matter to us.

In general line like the following indicate a positive acknowledgment

00000000     00                                      |.               |

One of the first lines in the file will be the queue name

00000000     02617363 0a                             |.asc.

Notice in the middle column that this begins with 02, this is a flag to indicate that this is the start of a print request. The name on the end of the line is the queue name.

Command Identifiers for LPD Defined in RFC

A status request for a queue would start with an 03. These binary identifiers are defined in the RFC.

01 - Print any waiting jobs.

02 - Receive a printer job

03 - Send queue state (short)

04 - Send queue state (long)
05 - Remove jobs

00000000     03617363 20200a                         |.asc  .         |

A short distance down the file a line will contain the temporary file name:

00000000     03353120 64664132 31396169 786e7473     |.51 dfA219aixnts|

In this case it begins with '03' in the middle column for 'data file' This is a subcommand of the Receive a printer job command.

Receive Printer Job Subcommands

01 - Abort job
02 - Receive control file

03 - Receive data file

The above example line shows a Receive data file subcommand with the following information:

The 51 in the 3rd column indicates the number of bytes in the file.
The file name starts with 'df' for data file.
The job number is the next part of the data file '219'.
The last part of the file name is the sending host name 'aixnts'.

The next packet of data from the client to the server will be the data file itself. Check this file for extraneous characters, line feeds, spaces, tabs and other things that might affect the format. The data in the right hand column should be exactly what was on the client.

00000010     31323334 35363738 393a3b3c 3d3e3f40     |123456789:;<=>?@|
00000020     41424344 45464748 494a4b4c 4d4e4f50     |ABCDEFGHIJKLMNOP|
00000030     51520a                                  |QR.             |

The next packet from the client is usually the control file name.

00000000     02313130 20636641 32313961 69786e74     |.110 cfA219aixnt|
00000010     730a                                    |s.              |

Again the subcommand for control file begins with '02' in the middle column. The information from the Receive control file is:

02 - this is a control file descriptor.
110 bytes of control file information.
The control file name starts with cfA
job number '219'
from host 'aixnts'.

Control file excerpt:

00000000     48616978 6e74730a 506a7774 65736368     |Haixnts.Pjwtesch|
00000010     0a666466 41323139 6169786e 74730a55     |.fdfA219aixnts.U|
00000020     64664132 31396169 786e7473 0a4e5354     |dfA219aixnts.NST|
00000030     44494e2e 36333834 350a2d4e 310a2d5a     |DIN.63845.-N1.-Z|
00000040     6a777465 73636840 6169786e 74730a2d     |jwtesch@aixnts.-|
00000050     746a7774 65736368 40616978 6e74730a     |tjwtesch@aixnts.|
00000060     2d545354 44494e2e 36333834 350a         |-TSTDIN.63845.  |

Control File Format
Flag	Description
Haixnts	shows the Hostname of the client.
Pjwtesch	shows the user identification
fdfA219aixnts	shows the file to print.
UdfA219aixnts	says unlink (delete) file when done.
NSTDIN.63845	Origin of the file
-N1	says make one copy
-Zjwtesch@aixnts	AIX originator of remote job flag
-tjwtesch@aixnts	AIX delivery flag.
-TSTDIN.63845	AIX Title flag.

The Control file lines defined by the rfc-1179

These flags do not require a minus (hyphen) and are universal. Other and enq flags will be in file with a - minus sign.

The Control file lines defined by the rfc-1179
C	Class for banner page
H	Host name
I	Indent Printing Used only with f columns
J	Job name for banner page
L	Print banner page
M	Mail When Printed
N	Name of source file
P	User identification
S	Symbolic link data Operand 1 - Device number Operand 2 - Inode number
T	Title for pr
U	Unlink data file
W	Width of output
1	troff R font
2	troff I font
3	troff B font
4	troff S font

Filter Flags AIX virtual printers see these as fc, where c is the character in the list below:
c	Plot CIF file Treat data as CalTech Intermediate Form
d	Print DVI fileTreat data as TeX output
f	Print formatted file Plain text, discard control chars.
g	Plot file Treat as Berkeley Unix Plot files.
l	Print file leaving control characters There have been problems with files coming to AIX. AIX virtual printer needs fl flag defined for these files to print. Typical problem from NT, Windows and OS/2.
n	Print ditroff output fileTreat as ditroff output, comes to AIX as -fn flag, need fn attribute defined. Usually uses filter like hplj or psc.
o	Print Postscript output file
p	Print file with 'pr' format
r	File to print with FORTRAN carriage control Usually means to use asa or fpr filter.
t	Print troff output file
v	Print raster file Print Sun raster format file.
z	Reserved for Palladium use

Error messages from the remote system usually show as text in the right hand column

Some of the things to look for in the output are:

There is always an initial handshake protocol that seems to look like:

00000000     020405ac                                |....
00000000     020405ac                                |....

The middle column always starts 02, I haven't figured out the rest.

In general line like the following indicate a positive acknowledgment

00000000     00                                      |.               |

One of the first lines in the file will be the queue name

00000000     02617363 0a                             |.asc.
             ^^

Notice in the middle column that this begins with 02, this is a flag to indicate that this is the start of a command sequence with the queue name.

A status request for a queue would start with an 03.

00000000     03617363 20200a                         |.asc  .         |

A short distance down the file a line will contain the temporary file name:

00000000     03353120 64664132 31396169 786e7473     |.51 dfA219aixnts|

In this case it begins with '03' in the middle column for 'data file'
The 51 in the 3rd column indicates the number of bytes in the file.
The file name starts with 'df' for data file.
The job number is the next part of the data file '219'.
The last part of the file name is the sending host name 'aixnts'.

00000010     31323334 35363738 393a3b3c 3d3e3f40     |123456789:;<=>?@|
00000020     41424344 45464748 494a4b4c 4d4e4f50     |ABCDEFGHIJKLMNOP|
00000030     51520a                                  |QR.             |

The next packet from the client is usually the control file name.

00000000     02313130 20636641 32313961 69786e74     |.110 cfA219aixnt|
00000010     730a                                    |s.              |

Again the subcommand for control file begins with '02' in the middle column.

The number of bytes is shown in the right column as '110'.

The name starts with 'cfA', is job number '219' from host 'aixnts'.

The following packed will be the actual control file.

00000000     48616978 6e74730a 506a7774 65736368     |Haixnts.Pjwtesch|
00000010     0a666466 41323139 6169786e 74730a55     |.fdfA219aixnts.U|
00000020     64664132 31396169 786e7473 0a4e5354     |dfA219aixnts.NST|
00000030     44494e2e 36333834 350a2d4e 310a2d5a     |DIN.63845.-N1.-Z|
00000040     6a777465 73636840 6169786e 74730a2d     |jwtesch@aixnts.-|
00000050     746a7774 65736368 40616978 6e74730a     |tjwtesch@aixnts.|
00000060     2d545354 44494e2e 36333834 350a         |-TSTDIN.63845.  |

Haixnts shows the Hostname of the client.
Pjwtesch shows the user identification
fdfA219aixnts shows the file to print.
UdfA219aixnts
NSTDIN.63845 Origin of the file
-N1 says make one copy
-Zjwtesch@aixnts
-tjwtesch@aixnts ?
-TSTDIN.63845

Error messages from the remote system usually show as text in the right hand column

For example using a bad backend I got the following message:

00000000     30373831 2d323031 20696c6c 2d666f72     |0781-201 ill-for|
00000010     6d656420 46524f4d 20616464 72657373     |med FROM address|
00000020     2e                                      |.               |

Sending data to a nonexistance queue on a remote machine gave:

00000000     756e6b6e 6f776e20 7072696e 74657220     |unknown printer |
00000010     62616471 2e                             |badq.           |

where 'badq' was the name of the queue I tried to send to.

Mail message for this was:

Message from qdaemon:
Device stimpy:dstimp died running request test.file which is still queued.

and

Message from qdaemon:

/usr/lpd/rembak -S stimpy.aix.dfw.ibm.com -P badq -N /usr/lpd/aixshort /tmp/test .file

Device stimpy:dstimp died running request test.file which is still queued.

Another common error is shown here:

00000000     30373831 2d323032 20796f75 7220686f     |0781-202 your ho|
00000010     73742064 6f657320 6e6f7420 68617665     |st does not have|
00000020     206c696e 65207072 696e7465 72206163     | line printer ac|
00000030     63657373 2e                             |cess.           |
mail messages:
Message from qdaemon:
rembak: (FATAL ERROR): Could not send datafile /tmp/test.file.
Message from qdaemon:
/usr/lpd/rembak -S vulcan.aix.dfw.ibm.com -P badq -N /usr/lpd/aixshort /tmp/test
.file
Message from qdaemon:
Device stimpy:dstimp died running request test.file which is still queued.
Message from qdaemon:
rembak: (FATAL ERROR): Could not send datafile /tmp/test.file.

Harder ones to find include unable to create file.

The Whole Packet Example

An example of the first packet of data is shown here:


=====( packet received on interface tr0 )=====Wed Jul 27 16:45:13 1994
802.5 packet

802.5 MAC header:
access control field = 18, frame control field = 40
[ src = 10:00:5a:4f:23:c4, dst = 10:00:5a:a8:84:9d]
802.2 LLC header:
dsap aa, ssap aa, ctrl 3, proto 0:0:0, type 800 (IP)
IP header breakdown:
        < SRC =     9.19.129.41 >  (parham.aix.dfw.ibm.com)
        < DST =     9.19.129.12 >  (tesch.aix.dfw.ibm.com)
        ip_v=4, ip_hl=20, ip_tos=0, ip_len=44, ip_id=44799, ip_off=0
        ip_ttl=60, ip_sum=bb71, ip_p = 6 (TCP)
TCP header breakdown:
        <source port=1023, destination port=515(printer) >
        th_seq=739daa01, th_ack=0
        th_off=6, flags<SYN |>
        th_win=16384, th_sum=2032, th_urp=0
00000000     020405ac                                |....            |

Lines of interest in debugging printing problems are:

Who sent the data?

< SRC = 9.19.129.41 > (parham.aix.dfw.ibm.com)
< DST = 9.19.129.12 > (tesch.aix.dfw.ibm.com)
<source port=1023, destination port=515(printer) >

How many bytes of data?

ip_v=4, ip_hl=20, ip_tos=0, ip_len=44, ip_id=44799, ip_off=0
ip_len=44 includes all packet information.

Sequence of data

th_seq=739daa01, th_ack=0 - first packet from source
th_seq=18967801, th_ack=739daa02 - first packet from dest.
th_seq=739daa02, th_ack=18967802 - from source
th_seq=739daa02, th_ack=18967802 - from source again
th_seq=18967802, th_ack=739daa0e - from destination

How much data can LPD accept?

If the 'th_win' field is 'th_win=0' the server is not accepting data.
th_win=15972, th_sum=414, th_urp=0

Type of operation One of the most valuable fields for debugging printing problems is the 'flags' field of the 'IP' packet. This field provides an indication of the type of packet that is being sent. Often the flags combined with the first byte of data indicate the handshaking and meaning of the data packet.

flag values

SYN - Sync (1st) packet from client, First part of 3 step handshake.
SYN | ACK Sync Acknowledge from server, Part 2 of handshake.
ACK - TCP/IP Acknowledgement of receipt, also Part 3 of initial handshake.
PUSH | ACK - Acknowledge receipt, and PUSH data to application. PUSH packets are the only true LPR/LPD packets.
FIN | ACK - Acknowledge receipt, and I am FINished with this session.
RST - Reset sequence, I'm done NOW.

Sample Job Sequence Excerpt

The sequence for a working print job between two RS/6000s follows:

        <source port=1023, destination port=515(printer) >
       th_off=6, flags<SYN |>             Sync (1st) packet from client
00000000     020405ac                     02 - requesting service ID

        <source port=515(printer), destination port=1023 >
        th_off=6, flags<SYN |ACK |>       Sync Acknowledge from server
00000000     020405ac                     Repeats data sequence.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<ACK |>            Acknowledge from client. No Data
                                          PUSH - push data to application.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<PUSH |ACK |>      Client sends print request '02'
00000000     02736d61 6c6c5f34 3033390a   for queue - |.small_4039.    |
        th_off=5, flags<PUSH |ACK |>      Send acknowledgement of data
00000000     00                           00 is AOK signal from server.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<PUSH |ACK |>      Client sends datafile name - 03
00000000     03313438 37206466 41343338 70617268     |.1487 dfA438parh|
        th_off=5, flags<ACK |>            Server acknowledge - no data

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<PUSH |ACK |>      lpd acknowledge to rembak
00000000     00                           00 - no problem, PUSH (application)
        th_off=5, flags<ACK |>            Actual data file from rembak
00000000     23204028 23293437 09312e31 2020636f     |# @(#)47.1.1  co|
        th_off=5, flags<PUSH |ACK |>      Second packet of data from rembak
00000000     392e3139 2e313239 2e343109 70617268     |9.19.129.41.parh|

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<ACK |>            server acknowledges data.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<PUSH |ACK |>      rembak says ok to lpd.
00000000     00                                      |.               |

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<PUSH |ACK |>      lpd says ok to rembak
00000000     00                                      |.               |

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<ACK |>            client acknowledges data done.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<PUSH |ACK |>      rembak sends control file name.
00000000     02313235 20636641 34333870 61726861     |.125 cfA438parha|

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<PUSH |ACK |>      lpd says ok, send it.
00000000     00                                      |.               |

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<PUSH |ACK |>      rembak sends control file
00000000     48706172 68616d0a 50726f6f 740a4a2f     |Hparham.Proot.J/|

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<ACK |>            server acknowledges receipt.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<PUSH |ACK |>      rembak says all sent.
00000000     00                                      |.               |

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<PUSH |ACK |>      lpd says all ok.
00000000     00                                      |.               |

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<ACK |>            client says ok

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<FIN |ACK |>       client says end of job - FIN!

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<ACK |>            server acknowledges FIN

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<PUSH |ACK |>      lpd says all ok with it.
00000000     00                                      |.               |

        <source port=515(printer), destination port=1023 >
        th_off=5, flags<FIN |ACK |>       lpd says end of job - FIN!

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<RST |>            client issues reset - RST.

        <source port=1023, destination port=515(printer) >
        th_off=5, flags<RST |>            client sends another RST.

Tracing Remote Printing: AIX Printer Tips: iptrace.html ITEM: FAX
Dated: 99/02/15~00:00 Category: zap
This HTML file was generated 99/06/24~12:42:12
Comments or suggestions? Contact us

AIX Printer Tips: Tracing Remote Printing

Contents

About This Document

What an iptrace Can Tell You

How To Do a Remote Trace

How To Interpret the Trace

A PostScript output might look something like this:

Information gained from this output

Command Identifiers for LPD Defined in RFC

Receive Printer Job Subcommands

Control file excerpt:

Control File Format

The Control file lines defined by the rfc-1179

The Control file lines defined by the rfc-1179

The Whole Packet Example

Sample Job Sequence Excerpt