Tracing Remote Printing

Contents

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 system 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

How To Do a Remote Trace

The 'iptrace' facility can easily show what is being sent to the remote system using the following commands:
  1. # iptrace -p printer -a -b -s source_host -d dest_host /tmp/trace.out
  2. # enq -Pqueue_name filename

  3. Print the job to the remote queue
    Or use lpstat -vqueue_name

  4. # ls -l /tmp/trace.out

  5. Check to see if the file has grown. If it is still 11 bytes, then you have done something wrong in your command, kill and retry.

  6. # ps -ef | grep ipt

  7. Get the job id
  8. # kill -9 job_id

  9. Kill the trace command
  10. # ipreport /tmp/trace.out > /tmp/report.out

  11. Format the output into a text file
The report contains three or four parts for each packet of data. These are:

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:

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. 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: This will show in the grep output as:
...
00000000     41414141 410a                           |AAAAA.          |
...
Notice that the data is divided into three columns. These are:
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
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.
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

The above example line shows a Receive data file subcommand with the following information: 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:
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|
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 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.  |
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:

Sample Job Sequence Excerpt

The sequence for a working print job between two systems 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.



[ Doc Ref: 9175597789870     Publish Date: Oct. 17, 2000     4FAX Ref: 6451 ]