1<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN"> 2 3<html> 4 <head> 5 <meta name="generator" content="HTML Tidy, see www.w3.org"> 6 <title>Debugging, Tracing, and Log Files</title> 7 <meta name="GENERATOR" content= 8 "Modular DocBook HTML Stylesheet Version 1.7"> 9 <link rel="HOME" title=" LPRng Reference Manual" href= 10 "index.htm"> 11 <link rel="UP" title="Print Spooling Tutorial " href= 12 "tutorial.htm"> 13 <link rel="PREVIOUS" title="Interfacing to Non-LPRng Spoolers" 14 href="x3885.htm"> 15 <link rel="NEXT" title= 16 "LPRng Clients - lpr, lprm, lpq, lpc, lpstat " href= 17 "lprngclients.htm"> 18 </head> 19 20 <body class="SECT1" bgcolor="#FFFFFF" text="#000000" link= 21 "#0000FF" vlink="#840084" alink="#0000FF"> 22 <div class="NAVHEADER"> 23 <table summary="Header navigation table" width="100%" border= 24 "0" cellpadding="0" cellspacing="0"> 25 <tr> 26 <th colspan="3" align="center">LPRng Reference Manual: 5 27 Sep 2003 (For LPRng-3.8.22)</th> 28 </tr> 29 30 <tr> 31 <td width="10%" align="left" valign="bottom"><a href= 32 "x3885.htm" accesskey="P">Prev</a></td> 33 34 <td width="80%" align="center" valign="bottom">Chapter 4. 35 Print Spooling Tutorial</td> 36 37 <td width="10%" align="right" valign="bottom"><a href= 38 "lprngclients.htm" accesskey="N">Next</a></td> 39 </tr> 40 </table> 41 <hr align="LEFT" width="100%"> 42 </div> 43 44 <div class="SECT1"> 45 <h1 class="SECT1"><a name="AEN3917">4.21. Debugging, Tracing, 46 and Log Files</a></h1> 47 48 <p>The <b class="APPLICATION">LPRng</b> software was designed 49 and written to provide as high a level of diagnostic 50 information as possible. This was largely in part due to the 51 problems with portability, coding errors, and other human 52 frailties. Approximately 80% of the <b class= 53 "APPLICATION">LPRng</b> source code concerns itself with 54 checking return values from system functions and producing 55 error messages, debugging and tracing information, and 56 various facilities used for regression testing and 57 diagnosis.</p> 58 59 <p>The approach used by <b class="APPLICATION">LPRng</b> is 60 to produce <span class="emphasis"><i class= 61 "EMPHASIS">trace</i></span> output for the <b class= 62 "APPLICATION">LPRng</b> clients or <span class="emphasis"><i 63 class="EMPHASIS">log</i></span> files for the <b class= 64 "APPLICATION">lpd</b> server that show the various events or 65 flow of information through the <b class= 66 "APPLICATION">LPRng</b> system. There are several classes or 67 types of actions that can be traced, and various levels of 68 trace information generated. The interface used to control 69 these actions are the command line <var class="LITERAL">-D 70 literals</var> flags and the <tt class="COMMAND">lpc 71 debug</tt> command.</p> 72 73 <p>First, we will look at how you can use the debugging 74 facilities for the clients. Enter the following commands:</p> 75 76 <div class="INFORMALEXAMPLE"> 77 <a name="AEN3932"></a> 78<pre class="SCREEN"> 79 <samp class="PROMPT">h4: {292} %</samp> <kbd class= 80"USERINPUT">lpr -D=</kbd> 81 debug usage: -D [ num | key=num | key=str | flag | flag@ | flag+N ]* 82 keys recognized: network[+N,@], database[+N,@], lpr[+N,@], 83 lpc[+N,@], lprm[+N,@], lpq[+N,@], test=num, job=num, log[+N,@] 84 <samp class="PROMPT">h4: {293} %</samp> <kbd class= 85"USERINPUT">lpr -V /tmp/hi</kbd> 86 LPRng-3.7.2, Copyright 1988-2000 Patrick Powell, <papowell@lprng.com> 87 sending job 'papowell@h4+981' to lp@localhost 88 connecting to 'localhost', attempt 1 89 connected to 'localhost' 90 requesting printer lp@localhost 91 sending control file 'cfA981h4.private' to lp@localhost 92 completed sending 'cfA981h4.private' to lp@localhost 93 sending data file 'dfA981h4.private' to lp@localhost 94 completed sending 'dfA981h4.private' to lp@localhost 95 done job 'papowell@h4+981' transfer to lp@localhost 96 <samp class="PROMPT">h4: {294} %</samp> <kbd class= 97"USERINPUT">lpr -D1 /tmp/hi</kbd> 98 09:38:08.707 h4 [13991] lpr Get_printer: original printer '<NULL>' 99 09:38:08.708 h4 [13991] lpr Get_all_printcap_entries: starting 100 09:38:08.708 h4 [13991] lpr Select_pc_info: looking for 'all', depth 0 101 09:38:08.708 h4 [13991] lpr Select_pc_info: returning '<NULL>' 102 09:38:08.708 h4 [13991] lpr Select_pc_info: looking for '*', depth 0 103 09:38:08.708 h4 [13991] lpr Select_pc_info: returning '<NULL>' 104 09:38:08.708 h4 [13991] lpr Dump_line_list: Get_all_printcap_entries 105 ... 106</pre> 107 </div> 108 <br> 109 <br> 110 111 <p>The <tt class="COMMAND">lpr -D=</tt> causes the <b class= 112 "APPLICATION">lpr</b> (and other <b class= 113 "APPLICATION">LPRng</b> programs) to show what debugging 114 flags are available. The <tt class="COMMAND">lpr -V</tt> flag 115 causes <b class="APPLICATION">lpr</b> to run in verbose mode 116 and show its activities. Finally, we use <tt class= 117 "COMMAND">lpr -D1</tt> to enable the simplest level of 118 debugging. This will produce a trace of the various 119 activities that <b class="APPLICATION">lpr</b> carries out. 120 Try <tt class="COMMAND">lpr -D2</tt>, <tt class="COMMAND">lpr 121 -D3</tt>, and so forth to see the increasing amount of detail 122 that you get.</p> 123 124 <p>The <span class="emphasis"><i class= 125 "EMPHASIS">network</i></span> and <span class="emphasis"><i 126 class="EMPHASIS">database</i></span> debug flags turn on 127 debugging for the network facilities and the database (<tt 128 class="FILENAME">lpd.conf</tt>, <tt class= 129 "FILENAME">printcap</tt>, and <tt class= 130 "FILENAME">lpd.perms</tt>) lookups. Lets see what <tt class= 131 "COMMAND">lpr -Dnetwork</tt> shows us:</p> 132 133 <div class="INFORMALEXAMPLE"> 134 <a name="AEN3957"></a> 135<pre class="SCREEN"> 136 C<samp class="PROMPT">h4: {295} %</samp> <kbd class= 137"USERINPUT">lpr -Dnetwork /tmp/hi</kbd> 138 lp: getconnection: START host localhost, timeout 10, connection_type 1 139 lp: getconnection: fqdn found localhost.private, h_addr_list count 1 140 lp: Link_dest_port_num: port 2000 = 2000 141 lp: getconnection: sock 3, src ip 127.0.0.1, port 65209 142 lp: getconnection: dest ip 127.0.0.1, port 2000 143 lp: getconnection: connection to 'localhost' sock 3, errmsg 'No Error' 144 lp: Link_send: host 'localhost' socket 3, timeout 6000 145 lp: Link_send: str '^Blp 146 ', count 4, ack 0x80447a0 147 lp: Link_send: final status NO ERROR 148 lp: Link_send: host 'localhost' socket 3, timeout 6000 149 lp: Link_send: str '^B135 cfA276h4.private 150 ', count 22, ack 0x8044370 151 lp: Link_send: final status NO ERROR 152 lp: Link_send: host 'localhost' socket 3, timeout 6000 153 lp: Link_send: str 'Hh4.private 154 Ppapowell 155 J/tmp/hi 156 CA 157 Lpapowell 158 Apapowell@h4+276 159 D2000-06-02-09:44:52.369 160 Qlp 161 N/tmp/hi 162 fdfA276h4.private 163 UdfA276h4.private 164 ', count 136, ack 0x8044370 165 lp: Link_send: final status NO ERROR 166 lp: Link_send: host 'localhost' socket 3, timeout 6000 167 lp: Link_send: str '^C3 dfA276h4.private 168 ', count 20, ack 0x8044310 169 lp: Link_send: final status NO ERROR 170 lp: Link_send: host 'localhost' socket 3, timeout 6000 171 lp: Link_send: str '', count 1, ack 0x8044310 172 lp: Link_send: final status NO ERROR 173</pre> 174 </div> 175 <br> 176 <br> 177 178 <p>As we see, we get a detailed exposition of the network 179 connection and transfer steps. If you need or want more 180 detail, try using <tt class="COMMAND">lpr -Dnetwork+2</tt> or 181 <tt class="COMMAND">lpr -Dnetwork+3</tt>. You may want to try 182 <tt class="COMMAND">lpr -Ddatabase</tt> and observe the 183 actions of the <b class="APPLICATION">lpr</b> program as it 184 extracts information from the <tt class= 185 "FILENAME">lpd.conf</tt> and <tt class= 186 "FILENAME">printcap</tt> files. If you need or want more 187 detail, try using <tt class="COMMAND">lpr -Ddatabase+2</tt> 188 or <tt class="COMMAND">lpr -Ddatabase+3</tt>.</p> 189 190 <p>If you need to trace the activities of the <b class= 191 "APPLICATION">lpd</b> server, it becomes a little more 192 complex. The lpd server has a single <span class= 193 "emphasis"><i class="EMPHASIS">listening</i></span> process 194 that forks and creates individual processes to handle 195 incoming requests. Debug or diagnose the main process actions 196 by using <tt class="COMMAND">lpd -D...</tt>. You may also 197 want to use <tt class="COMMAND">lpd -F</tt> to keep the 198 server in the foreground so you can kill it off easily. 199 Needless to say, you should also redirect the <acronym class= 200 "ACRONYM">STDERR</acronym> and <acronym class= 201 "ACRONYM">STDOUT</acronym> so that it goes to a file so that 202 you can examine the voluminous records at your leisure. The 203 following shows a typical main <b class="APPLICATION">lpd</b> 204 process debugging session using the C Shell.</p> 205 206 <div class="INFORMALEXAMPLE"> 207 <a name="AEN3978"></a> 208<pre class="SCREEN"> 209 <samp class="PROMPT">h4: {296} %</samp> <kbd class= 210"USERINPUT">lpd -F -D1 >&/tmp/logfile &</kbd> 211 [2] 14299 212 <samp class="PROMPT">h4: {297} %</samp> <kbd class= 213"USERINPUT">tail -f /tmp/logfile</kbd> 214 2000-06-02-09:53:39.716 h4 [1200] Waiting Read_server_status: \ 215 select status 1 216 2000-06-02-09:53:39.716 h4 [1200] Waiting Read_server_status: \ 217 read status 1 218 2000-06-02-09:53:39.716 h4 [1200] Waiting Dump_line_list: \ 219 Read_server_status - input - 0x8047980, count 0, max 0, list 0x0 220 2000-06-02-09:53:39.716 h4 [1200] Waiting Read_server_status: \ 221 select status 0 222 2000-06-02-09:53:39.716 h4 [1200] Waiting lpd: LOOP START 223 2000-06-02-09:53:39.716 h4 [1200] Waiting Get_max_servers: \ 224 getrlimit returns 64 225 2000-06-02-09:53:39.716 h4 [1200] Waiting Get_max_servers: \ 226 returning 32 227 2000-06-02-09:53:39.716 h4 [1200] Waiting lpd: \ 228 max_servers 32, active 0 229 2000-06-02-09:53:39.716 h4 [1200] Waiting lpd: \ 230 starting select timeout 'yes' 231 232 ^C 233 <samp class="PROMPT">h4: {298} %</samp> <kbd class= 234"USERINPUT">jobs</kbd> 235 [1] - Running lpd -F -D1 >& /tmp/logfile 236 <samp class="PROMPT">h4: {299} %</samp> <kbd class= 237"USERINPUT">kill %1</kbd> 238</pre> 239 </div> 240 <br> 241 <br> 242 243 <p>We start the debugging session by running the <b class= 244 "APPLICATION">lpd</b> server in foreground mode. This causes 245 it to send its output to <acronym class= 246 "ACRONYM">STDOUT</acronym> and <acronym class= 247 "ACRONYM">STDERR</acronym>. We redirect both of these to a 248 file and put the <b class="APPLICATION">lpd</b> server in the 249 background. Then we use <tt class="COMMAND">tail -f</tt> to 250 read from the log file. Finally, we kill off the <b class= 251 "APPLICATION">lpd</b> server.</p> 252 253 <p>This method is extremely difficult to use, as all of the 254 output produced by the server and its subprocesses is sent to 255 a single output file. If we want to debug the actions 256 concerning a single queue, then we can use the queue <span 257 class="emphasis"><i class="EMPHASIS">log file</i></span> and 258 <tt class="COMMAND">lpc debug</tt> command instead. The 259 following options control debugging of an individual print 260 queue.</p> 261 262 <div class="VARIABLELIST"> 263 <dl> 264 <dt>lf=log</dt> 265 266 <dd> 267 <p>The log file for the queue. The queue server process 268 will open this file and place debugging information 269 into this file.</p> 270 </dd> 271 272 <dt>max_log_file_size=nnn</dt> 273 274 <dd> 275 <p>The maximum size of the log file in K bytes. When 276 the queue server process first opens this file it will 277 check to see if the file is larger than the maximum 278 size. If it is, then it will truncate it. A zero (0) 279 value suppress truncation.</p> 280 </dd> 281 282 <dt>min_log_file_size=nnn</dt> 283 284 <dd> 285 <p>When the log file is truncated only the the last nnn 286 K bytes are retained.</p> 287 </dd> 288 289 <dt>db=options</dt> 290 291 <dd> 292 <p>These are debugging options for the spool queue. 293 These options are permanent and cannot be changed by 294 using the <tt class="COMMAND">lpc debug</tt> 295 facility.</p> 296 </dd> 297 </dl> 298 </div> 299 <br> 300 <br> 301 302 <p>The <tt class="COMMAND">lpc debug</tt> command is used to 303 set the debugging options in force for the spool queue. This 304 is done by writing the debug options into the spool queue 305 control file. Let us see how we can use this facility to 306 trace the actions of printing a file.</p> 307 308 <p>Edit the printcap file so it have the contents indicated 309 below, create the <tt class="FILENAME">/tmp/lp</tt> and <tt 310 class="FILENAME">/tmp/lp2</tt> files with <var class= 311 "LITERAL">0777</var> permissions. Use <tt class= 312 "COMMAND">checkpc -f</tt> to check the printcap, and then use 313 <tt class="COMMAND">lpc reread</tt> to restart the <b class= 314 "APPLICATION">lpd</b> server.</p> 315 316 <div class="INFORMALEXAMPLE"> 317 <a name="AEN4025"></a> 318<pre class="SCREEN"> 319 # printcap 320 lp:force_localhost 321 lp:server 322 :lp=/dev/null 323 :sd=/var/spool/lpd/%P 324 :lf=log 325 lp2:force_localhost 326 lp2:server 327 :sd=/var/spool/lpd/%P 328 :lp=/tmp/lp2 329 :lf=log 330</pre> 331 </div> 332 <br> 333 <br> 334 335 <p>Now execute the following commands:</p> 336 337 <div class="INFORMALEXAMPLE"> 338 <a name="AEN4028"></a> 339<pre class="SCREEN"> 340 <samp class="PROMPT">h4: {300} %</samp> <kbd class= 341"USERINPUT">lpq</kbd> 342 Printer: lp@h4 343 Queue: no printable jobs in queue 344 <samp class="PROMPT">h4: {301} %</samp> <kbd class= 345"USERINPUT">lpc debug lp 1</kbd> 346 Printer: lp@h4 347 debugging override set to '1' 348 lp@h4.private: updated 349 <samp class="PROMPT">h4: {302} %</samp> <kbd class= 350"USERINPUT">lpc status</kbd> 351 Printer Printing Spooling Jobs Server Subserver Redirect Status/(Debug) 352 lp@h4 enabled enabled 0 none none (1) 353 <samp class="PROMPT">h4: {303} %</samp> <kbd class= 354"USERINPUT">lpr /tmp/hi</kbd> 355 <samp class="PROMPT">h4: {304} %</samp> <kbd class= 356"USERINPUT">more /var/spool/lpd/lp2/log</kbd> 357 2000-06-02-10:10:50.589 h4 [1201] (Server) lp: \ 358 Update_spool_info: printer 'lp' 359 2000-06-02-10:10:50.590 h4 [1201] (Server) lp: \ 360 Do_queue_jobs: printable 1, held 0, move 0 361 2000-06-02-10:10:50.590 h4 [1201] (Server) lp: \ 362 Do_queue_jobs: after Scan_queue next fd 5 363 2000-06-02-10:10:50.590 h4 [1201] (Server) lp: \ 364 Do_queue_jobs: MAIN LOOP 365 2000-06-02-10:10:50.590 h4 [1201] (Server) lp: \ 366 Do_queue_jobs: Susr1 before scan 0 367 2000-06-02-10:10:50.591 h4 [1201] (Server) lp: \ 368 Do_queue_jobs: chooser '<NULL>', chooser_routine 0 369</pre> 370 </div> 371 <br> 372 <br> 373 374 <p>The <tt class="COMMAND">lpc debug</tt> command sets the 375 debug level to 1. We can use the <tt class="COMMAND">lpc 376 status</tt> command to see what debug flags or actions are 377 currently specified for the spool queue. We then send a job 378 to the spool queue and examine the log file contents.</p> 379 380 <p>Each line in the log file has a timestamp, the name of the 381 host, the process id that produced it, and a heading that 382 tells the action or activity that the process is performing, 383 and the name of the print queue that is being processed and a 384 trace message. By convention, the trace message lists the 385 name of the routine that processed it and then the actual 386 information. Some messages may extend over several lines, but 387 each line has the standard header at the start of the 388 line.</p> 389 390 <p>The default debug or trace actions were designed to trace 391 problems with printing, as these are the most common. 392 However, you can also use the <b class="APPLICATION">lpr</b>, 393 <b class="APPLICATION">lpc</b>, <b class= 394 "APPLICATION">lprm</b>, or <b class="APPLICATION">lpq</b> 395 option to cause the <b class="APPLICATION">lpd</b> server to 396 trace the actions during the execution of an <b class= 397 "APPLICATION">lpr</b>, <b class="APPLICATION">lpc</b>, <b 398 class="APPLICATION">lprm</b>, or <b class= 399 "APPLICATION">lpq</b> request.</p> 400 401 <p>The <span class="emphasis"><i class= 402 "EMPHASIS">log</i></span> option is used to test various 403 logging facilities and is usually not used for general 404 purpose debugging.</p> 405 </div> 406 407 <div class="NAVFOOTER"> 408 <hr align="LEFT" width="100%"> 409 410 <table summary="Footer navigation table" width="100%" border= 411 "0" cellpadding="0" cellspacing="0"> 412 <tr> 413 <td width="33%" align="left" valign="top"><a href= 414 "x3885.htm" accesskey="P">Prev</a></td> 415 416 <td width="34%" align="center" valign="top"><a href= 417 "index.htm" accesskey="H">Home</a></td> 418 419 <td width="33%" align="right" valign="top"><a href= 420 "lprngclients.htm" accesskey="N">Next</a></td> 421 </tr> 422 423 <tr> 424 <td width="33%" align="left" valign="top">Interfacing to 425 Non-LPRng Spoolers</td> 426 427 <td width="34%" align="center" valign="top"><a href= 428 "tutorial.htm" accesskey="U">Up</a></td> 429 430 <td width="33%" align="right" valign="top"><b class= 431 "APPLICATION">LPRng</b> Clients - lpr, lprm, lpq, lpc, 432 lpstat</td> 433 </tr> 434 </table> 435 </div> 436 </body> 437</html> 438 439