IBM Support

Tracing Remote Printing

Question & Answer


Question

Tracing Remote Printing

Answer

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 all levels of AIX Versions 4 and 5.

What an iptrace can tell you
How to do a remote trace
How to interpret the trace
Command identifiers for LPD defined in RFC
Receive printer job subcommands
Control file format
The whole packet example
Sample job sequence excerpt

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:
  1. # 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

  2. # enq -Pqueue_name filename

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

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

    4. 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.

  4. # ps -ef | grep ipt

    5. Get the job id

  5. # kill -9 job_id

    6. Kill the trace command

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

    7. Format the output into a text file
The report contains three or four parts for each packet of data. These are:
  • MAC header
  • IP header
  • TCP header
  • 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

    • This is important because of the multitasking environment. Packets from a status can be interspersed with packets from a print job, but for a single job the source port will remain the same.

  • packet identification.

    • Use th_seq and th_ack to make sure the packets are in order, and to see which packet an ACK is responding to.

  • window size th_win

    • The data packet shows the actual data that is sent back and forth.
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            &nbs
p;             
 |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            &nbs
p;     the characters.
!packet
00000000     
020405ac            
             &n
bsp;      
|....            |
00000000     
020405ac            
             &n
bsp;      
|....            |
00000000     0268705f 706f7374 
0a             
       
|.hp_post.       |
00000000     
00             
             &n
bsp;           
|.             
  |
00000000     03363433 36382064 66413132 
30746573     |.64368 dfA120tes|
00000010     
63680a            &n
bsp;            &nbs
p;        
|ch.             |
00000000     
00             
             &n
bsp;           
|.             
  |
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            
             &n
bsp;      |....
00000000     
020405ac            
             &n
bsp;      |....
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             
             &n
bsp;           
|.             
  |
One of the first lines in the file will be the queue name 
00000000     02617363 
0a             
             &n
bsp;  |.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.

    • Not supported by AIX rembak.
  • 02 - Receive a printer job

    • Standard command for printing.
  • 03 - Send queue state (short)

    • Default status with qchk, lpstat, enq -A
  • 04 - Send queue state (long)
  • 05 - Remove jobs
00000000     03617363 
20200a            &n
bsp;            
|.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

    • | 02 | Count | SP | Name | LF |
  • 03 - Receive data file

    • | 03 | Count | SP | Name | LF |
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            &n
bsp;            &nbs
p;        
|QR.             
|
The next packet from the client is usually the control file name. 
00000000     02313130 20636641 
32313961 69786e74     |.110 cfA219aixnt|
00000010     
730a            &nbs
p;             
          
|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            
             &n
bsp;      |....
00000000     
020405ac            
             &n
bsp;      |....
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             
             &n
bsp;           
|.             
  |
One of the first lines in the file will be the queue name 
00000000     02617363 
0a             
             &n
bsp;  |.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            &n
bsp;            
|.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'.
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            &n
bsp;            &nbs
p;        
|QR.             
|
The next packet from the client is usually the control file name. 
00000000     02313130 20636641 32313961 
69786e74     |.110 cfA219aixnt|
00000010     
730a            &nbs
p;             
          
|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             
             &n
bsp;           
|.             
  |
Sending data to a nonexistance queue on a remote machine gave: 
00000000     756e6b6e 6f776e20 7072696e 
74657220     |unknown printer |
00000010     62616471 
2e             
             &n
bsp;  |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             
             &n
bsp;  |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            
             &n
bsp;      
|....            
|
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.

      • Since we have 4 bytes of real data, we conclude the MAC+IP+TCP took 40 bytes for this job. We can now get data bytes by subtracting 40 from the ip_len.

  • Sequence of data

    • The sequence of packets though the network are maintained by a sequence number. th_seq will be a large number for the first packet, and after the handshake is established will equal the th_ack from the last packet from the other system. th_ack=0 indicates this is the first packet of the sequence. After this it will contain the th_seq from the last system plus the number of 'data' bytes in the last packet. A series of packets might look like:
    • 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 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
             &n
bsp;            &nbs
p;             
  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             
             &n
bsp;           
|.             
  |
        <source port=515(printer), 
destination port=1023 >
        th_off=5, flags<PUSH |ACK 
|>      lpd says ok to rembak
00000000     
00             
             &n
bsp;           
|.             
  |
        <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             
             &n
bsp;           
|.             
  |
        <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             
             &n
bsp;           
|.             
  |
        <source port=515(printer), 
destination port=1023 >
        th_off=5, flags<PUSH |ACK 
|>      lpd says all ok.
00000000     
00             
             &n
bsp;           
|.             
  |
        <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             
             &n
bsp;           
|.             
  |
        <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.

[{"Product":{"code":"SWG10","label":"AIX"},"Business Unit":{"code":"BU058","label":"IBM Infrastructure w\/TPS"},"Component":"Attached devices","Platform":[{"code":"PF002","label":"AIX"}],"Version":"5.3;5.2;5.1;4.3","Edition":"","Line of Business":{"code":"LOB08","label":"Cognitive Systems"}}]

Historical Number

isg1pTechnote0377

Document Information

Modified date:
17 June 2018

UID

isg3T1000239

Page Feedback