Multiple copies in selfwritten backend

Mario Goppold ml at goppold.net
Wed Jul 18 13:41:21 PDT 2007


I have more tested and found that there are no backend calls for the 2,3,... files:

     1  d [18/Jul/2007:22:20:47 +0200] POST /printers/MYTEST
     2  d [18/Jul/2007:22:20:47 +0200] CONTENT_TYPE = application/ipp
     3  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=255, con->file=-1
     4  d [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest(0x8007dc50[7]): operation_id = 0005
     5  D [18/Jul/2007:22:20:47 +0200] Create-Job ipp://localhost/printers/MYTEST
     6  d [18/Jul/2007:22:20:47 +0200] create_job(0x8007dc50[7], ipp://localhost/printers/MYTEST)
     7  d [18/Jul/2007:22:20:47 +0200] add_job(0x8007dc50[7], ipp://localhost/printers/MYTEST)
     8  d [18/Jul/2007:22:20:47 +0200] cupsdFindPolicyOp(p=0x8005ffb0, op=5(Create-Job))
     9  d [18/Jul/2007:22:20:47 +0200] cupsdFindPolicyOp: Found wildcard match...
    10  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: con->uri="/printers/MYTEST", con->best=0x80061200((null))
    11  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
    12  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: op=0(unknown-0000)
    13  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: auth=AUTH_ALLOW...
    14  d [18/Jul/2007:22:20:47 +0200] check_quotas(0x8007dc50[7], 0x8006cea8[MYTEST])
    15  D [18/Jul/2007:22:20:47 +0200] add_job: requesting-user-name="mario"
    16  I [18/Jul/2007:22:20:47 +0200] Adding start banner page "none" to job 129.
    17  d [18/Jul/2007:22:20:47 +0200] copy_banner(0x8007dc50[7], 0x80074a78[129], none)
    18  d [18/Jul/2007:22:20:47 +0200] add_job_state_reasons(0x8007dc50[7], 129)
    19  d [18/Jul/2007:22:20:47 +0200] cupsdAddEvent(event=job-created, dest=0x8006cea8(MYTEST), job=0x80074a78(129), text="Job created.", ...)
    20  D [18/Jul/2007:22:20:47 +0200] Discarding unused job-created event...
    21  d [18/Jul/2007:22:20:47 +0200] cupsdSaveJob(job=0x80074a78(129)): job->attrs=0x800739e0
    22  I [18/Jul/2007:22:20:47 +0200] Job 129 created on "MYTEST" by "mario".
    23  D [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest: 7 status_code=0 (successful-ok)
    24  d [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest: Adding fd 7 to OutputSet...
    25  d [18/Jul/2007:22:20:47 +0200] cupsdWriteClient: 7 bytes < 0
    26  d [18/Jul/2007:22:20:47 +0200] cupsdWriteClient: Removing fd 7 from OutputSet...
    27  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7, used=0, file=-1 state=0
    28  D [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 POST /printers/MYTEST HTTP/1.1
    29  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: uri = "/printers/MYTEST"...
    30  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
    31  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location /admin/conf Limit 7f
    32  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location /admin Limit 7f
    33  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location / Limit 7f
    34  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: best = /
    35  d [18/Jul/2007:22:20:47 +0200] cupsdAuthorize: con->uri="/printers/MYTEST", con->best=0x8005fdb0(/)
    36  d [18/Jul/2007:22:20:47 +0200] cupsdAuthorize: Authorization=""
    37  D [18/Jul/2007:22:20:47 +0200] cupsdAuthorize: No authentication data provided.
    38  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: con->uri="/printers/MYTEST", con->best=0x8005fdb0(/)
    39  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
    40  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: auth=AUTH_ALLOW...
    41  d [18/Jul/2007:22:20:47 +0200] POST /printers/MYTEST
    42  d [18/Jul/2007:22:20:47 +0200] CONTENT_TYPE = application/ipp
    43  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=1907, con->file=-1
    44  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 REQUEST /var/spool/cups/00000002=9
    45  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 writing 1687 bytes to 9
    46  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 Closing data file 9, size=1687.
    47  d [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest(0x8007dc50[7]): operation_id = 0006
    48  D [18/Jul/2007:22:20:47 +0200] Send-Document ipp://localhost/jobs/129
    49  d [18/Jul/2007:22:20:47 +0200] send_document(0x8007dc50[7], ipp://localhost/jobs/129)
    50  d [18/Jul/2007:22:20:47 +0200] validate_user(job=129, con=7, owner="mario", username=0xbf815a72, userlen=1024)
    51  d [18/Jul/2007:22:20:47 +0200] cupsdFindPolicyOp(p=0x8005ffb0, op=6(Send-Document))
    52  d [18/Jul/2007:22:20:47 +0200] cupsdFindPolicyOp: Found exact match...
    53  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: con->uri="/printers/MYTEST", con->best=0x8005ffe0((null))
    54  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: owner="mario"
    55  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: level=AUTH_USER, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=2
    56  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: op=6(Send-Document)
    57  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: auth=AUTH_ALLOW...
    58  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: requesting-user-name="mario"
    59  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: Checking user membership...
    60  D [18/Jul/2007:22:20:47 +0200] send_document: auto-typing file...
    61  D [18/Jul/2007:22:20:47 +0200] send_document: request file type is text/plain.
    62  d [18/Jul/2007:22:20:47 +0200] add_file(con=0x8007dc50[7], job=129, filetype=text/plain, compression=0)
    63  I [18/Jul/2007:22:20:47 +0200] File of type text/plain queued in job #129 by "mario".
    64  d [18/Jul/2007:22:20:47 +0200] cupsdSaveJob(job=0x80074a78(129)): job->attrs=0x800739e0
    65  d [18/Jul/2007:22:20:47 +0200] add_job_state_reasons(0x8007dc50[7], 129)
    66  D [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest: 7 status_code=0 (successful-ok)
    67  d [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest: Adding fd 7 to OutputSet...
    68  d [18/Jul/2007:22:20:47 +0200] cupsdWriteClient: 7 bytes < 0
    69  d [18/Jul/2007:22:20:47 +0200] cupsdWriteClient: Removing fd 7 from OutputSet...
    70  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7, used=0, file=-1 state=0
    71  D [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 POST /printers/MYTEST HTTP/1.1
    72  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: uri = "/printers/MYTEST"...
    73  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location CUPS_INTERNAL_BROWSE_ACL Limit 0
    74  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location /admin/conf Limit 7f
    75  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location /admin Limit 7f
    76  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: Location / Limit 7f
    77  d [18/Jul/2007:22:20:47 +0200] cupsdFindBest: best = /
    78  d [18/Jul/2007:22:20:47 +0200] cupsdAuthorize: con->uri="/printers/MYTEST", con->best=0x8005fdb0(/)
    79  d [18/Jul/2007:22:20:47 +0200] cupsdAuthorize: Authorization=""
    80  D [18/Jul/2007:22:20:47 +0200] cupsdAuthorize: No authentication data provided.
    81  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: con->uri="/printers/MYTEST", con->best=0x8005fdb0(/)
    82  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: level=AUTH_ANON, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=0
    83  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: auth=AUTH_ALLOW...
    84  d [18/Jul/2007:22:20:47 +0200] POST /printers/MYTEST
    85  d [18/Jul/2007:22:20:47 +0200] CONTENT_TYPE = application/ipp
    86  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 con->data_encoding=HTTP_ENCODE_LENGTH, con->data_remaining=926, con->file=-1
    87  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 REQUEST /var/spool/cups/00000003=9
    88  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 writing 688 bytes to 9
    89  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7 Closing data file 9, size=688.
    90  d [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest(0x8007dc50[7]): operation_id = 0006
    91  D [18/Jul/2007:22:20:47 +0200] Send-Document ipp://localhost/jobs/129
    92  d [18/Jul/2007:22:20:47 +0200] send_document(0x8007dc50[7], ipp://localhost/jobs/129)
    93  d [18/Jul/2007:22:20:47 +0200] validate_user(job=129, con=7, owner="mario", username=0xbf815a72, userlen=1024)
    94  d [18/Jul/2007:22:20:47 +0200] cupsdFindPolicyOp(p=0x8005ffb0, op=6(Send-Document))
    95  d [18/Jul/2007:22:20:47 +0200] cupsdFindPolicyOp: Found exact match...
    96  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: con->uri="/printers/MYTEST", con->best=0x8005ffe0((null))
    97  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: owner="mario"
    98  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: level=AUTH_USER, type=AUTH_NONE, satisfy=AUTH_SATISFY_ALL, num_names=2
    99  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: op=6(Send-Document)
   100  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: auth=AUTH_ALLOW...
   101  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: requesting-user-name="mario"
   102  d [18/Jul/2007:22:20:47 +0200] cupsdIsAuthorized: Checking user membership...
   103  D [18/Jul/2007:22:20:47 +0200] send_document: auto-typing file...
   104  D [18/Jul/2007:22:20:47 +0200] send_document: request file type is text/plain.
   105  d [18/Jul/2007:22:20:47 +0200] add_file(con=0x8007dc50[7], job=129, filetype=text/plain, compression=0)
   106  I [18/Jul/2007:22:20:47 +0200] File of type text/plain queued in job #129 by "mario".
   107  I [18/Jul/2007:22:20:47 +0200] Adding end banner page "none" to job 129.
   108  d [18/Jul/2007:22:20:47 +0200] copy_banner(0x8007dc50[7], 0x80074a78[129], none)
   109  d [18/Jul/2007:22:20:47 +0200] cupsdSaveJob(job=0x80074a78(129)): job->attrs=0x800739e0
   110  d [18/Jul/2007:22:20:47 +0200] cupsdCheckJobs: 1 active jobs, sleeping=0, reload=0
   111  d [18/Jul/2007:22:20:47 +0200] cupsdCheckJobs: Job 129: state_value=3, loaded=yes
   112  d [18/Jul/2007:22:20:47 +0200] start_job: id = 129, file = 0/2
   113  D [18/Jul/2007:22:20:47 +0200] [Job 129] Sending job to queue tagged as raw...
   114  d [18/Jul/2007:22:20:47 +0200] cupsdAddEvent(event=printer-state-changed, dest=0x8006cea8(MYTEST), job=(nil)(0), text="%s "%s" state changed.", ...)
   115  D [18/Jul/2007:22:20:47 +0200] Discarding unused printer-state-changed event...
   116  D [18/Jul/2007:22:20:47 +0200] job-sheets=none,none
   117  D [18/Jul/2007:22:20:47 +0200] banner_page = 0
   118  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[0]="MYTEST"
   119  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[1]="129"
   120  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[2]="mario"
   121  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[3]="passwd"
   122  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[4]="1"
   123  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[5]="job-uuid=urn:uuid:f578adf9-bea6-30ef-515d-504bef710bec"
   124  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[6]="/var/spool/cups/d00129-001"
   125  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
   126  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[1]="CUPS_DATADIR=/usr/share/cups"
   127  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[2]="CUPS_DOCROOT=/usr/share/doc/packages/cups"
   128  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
   129  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
   130  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
   131  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[6]="CUPS_SERVERROOT=/etc/cups"
   132  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[7]="CUPS_STATEDIR=/var/run/cups"
   133  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
   134  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[9]="SERVER_ADMIN=root at localhost"
   135  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[10]="SOFTWARE=CUPS/1.2.7"
   136  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[11]="TMPDIR=/var/spool/cups/tmp"
   137  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[12]="USER=root"
   138  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
   139  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[14]="CUPS_ENCRYPTION=IfRequested"
   140  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[15]="IPP_PORT=631"
   141  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[16]="CHARSET=iso-8859-15"
   142  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[17]="LANG=C"
   143  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[18]="PPD=/etc/cups/ppd/MYTEST.ppd"
   144  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[19]="RIP_MAX_CACHE=8m"
   145  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[20]="CONTENT_TYPE=text/plain"
   146  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[21]="DEVICE_URI=mytest://dummy"
   147  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[22]="PRINTER=MYTEST"
   148  d [18/Jul/2007:22:20:47 +0200] start_job: status_pipes = [ 11 12 ]
   149  d [18/Jul/2007:22:20:47 +0200] start_job: backend="/usr/lib/cups/backend/mytest"
   150  d [18/Jul/2007:22:20:47 +0200] start_job: filterfds[0] = [ -1 -1 ]
   151  d [18/Jul/2007:22:20:47 +0200] cupsdStartProcess("/usr/lib/cups/backend/mytest", 0x80084158, 0xbf8120e8, -1, -1, 12)
   152  I [18/Jul/2007:22:20:47 +0200] Started backend /usr/lib/cups/backend/mytest (PID 14872) for job 129.
   153  d [18/Jul/2007:22:20:47 +0200] start_job: Closing filter pipes for slot 0 [ -1 -1 ]...
   154  d [18/Jul/2007:22:20:47 +0200] start_job: Adding fd 11 to InputSet...
   155  d [18/Jul/2007:22:20:47 +0200] cupsdAddEvent(event=job-state, dest=0x8006cea8(MYTEST), job=0x80074a78(129), text="Job #%d started.", ...)
   156  D [18/Jul/2007:22:20:47 +0200] Discarding unused job-state event...
   157  d [18/Jul/2007:22:20:47 +0200] add_job_state_reasons(0x8007dc50[7], 129)
   158  D [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest: 7 status_code=0 (successful-ok)
   159  d [18/Jul/2007:22:20:47 +0200] cupsdProcessIPPRequest: Adding fd 7 to OutputSet...
   160  d [18/Jul/2007:22:20:47 +0200] cupsdWriteClient: 7 bytes < 0
   161  d [18/Jul/2007:22:20:47 +0200] cupsdWriteClient: Removing fd 7 from OutputSet...
   162  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: 7, used=0, file=-1 state=0
   163  d [18/Jul/2007:22:20:47 +0200] cupsdReadClient: httpGets returned EOF...
   164  D [18/Jul/2007:22:20:47 +0200] cupsdCloseClient: 7
   165  d [18/Jul/2007:22:20:47 +0200] cupsdCloseClient: Removing fd 7 from InputSet and OutputSet...
   166  D [18/Jul/2007:22:20:47 +0200] [Job 129] job     =129
   167  D [18/Jul/2007:22:20:47 +0200] [Job 129] user    =mario
   168  D [18/Jul/2007:22:20:47 +0200] [Job 129] title   =passwd
   169  D [18/Jul/2007:22:20:47 +0200] [Job 129] copies  =1
   170  D [18/Jul/2007:22:20:47 +0200] [Job 129] options =job-uuid=urn:uuid:f578adf9-bea6-30ef-515d-504bef710bec
   171  D [18/Jul/2007:22:20:47 +0200] [Job 129] filename=/var/spool/cups/d00129-001
   172  D [18/Jul/2007:22:20:47 +0200] [Job 129] CUPS_SERVERADMIN=root at localhost
   173  D [18/Jul/2007:22:20:47 +0200] [Job 129] cmdln=/usr/bin/wc -c /var/spool/cups/d00129-001 >> /tmp/debug_cups_test
   174  D [18/Jul/2007:22:20:47 +0200] [Job 129] realprinter=dummy
   175  d [18/Jul/2007:22:20:47 +0200] process_children()
   176  D [18/Jul/2007:22:20:47 +0200] PID 14872 (/usr/lib/cups/backend/mytest) exited with no errors.
   177  D [18/Jul/2007:22:20:47 +0200] [Job 129] File 0 is complete.
   178  d [18/Jul/2007:22:20:47 +0200] cupsdFinishJob: job->status is 0
   179  d [18/Jul/2007:22:20:47 +0200] start_job: id = 129, file = 1/2
   180  D [18/Jul/2007:22:20:47 +0200] [Job 129] Sending job to queue tagged as raw...
   181  D [18/Jul/2007:22:20:47 +0200] job-sheets=none,none
   182  D [18/Jul/2007:22:20:47 +0200] banner_page = 0
   183  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[0]="MYTEST"
   184  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[1]="129"
   185  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[2]="mario"
   186  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[3]="passwd"
   187  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[4]="1"
   188  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[5]="job-uuid=urn:uuid:f578adf9-bea6-30ef-515d-504bef710bec"
   189  D [18/Jul/2007:22:20:47 +0200] [Job 129] argv[6]="/var/spool/cups/d00129-002"
   190  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
   191  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[1]="CUPS_DATADIR=/usr/share/cups"
   192  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[2]="CUPS_DOCROOT=/usr/share/doc/packages/cups"
   193  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
   194  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
   195  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
   196  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[6]="CUPS_SERVERROOT=/etc/cups"
   197  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[7]="CUPS_STATEDIR=/var/run/cups"
   198  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
   199  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[9]="SERVER_ADMIN=root at localhost"
   200  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[10]="SOFTWARE=CUPS/1.2.7"
   201  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[11]="TMPDIR=/var/spool/cups/tmp"
   202  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[12]="USER=root"
   203  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[13]="CUPS_SERVER=/var/run/cups/cups.sock"
   204  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[14]="CUPS_ENCRYPTION=IfRequested"
   205  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[15]="IPP_PORT=631"
   206  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[16]="CHARSET=iso-8859-15"
   207  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[17]="LANG=C"
   208  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[18]="PPD=/etc/cups/ppd/MYTEST.ppd"
   209  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[19]="RIP_MAX_CACHE=8m"
   210  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[20]="CONTENT_TYPE=text/plain"
   211  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[21]="DEVICE_URI=mytest://dummy"
   212  D [18/Jul/2007:22:20:47 +0200] [Job 129] envp[22]="PRINTER=MYTEST"
   213  d [18/Jul/2007:22:20:47 +0200] start_job: Closing print pipes [ -1 -1 ]...
   214  d [18/Jul/2007:22:20:47 +0200] start_job: Closing back pipes [ 9 10 ]...
   215  d [18/Jul/2007:22:20:47 +0200] start_job: Closing status output pipe 12...
   216  d [18/Jul/2007:22:20:47 +0200] start_job: Closing filter pipes for slot 0 [ -1 -1 ]...
   217  d [18/Jul/2007:22:20:47 +0200] start_job: Adding fd 11 to InputSet...
   218  d [18/Jul/2007:22:20:47 +0200] cupsdAddEvent(event=job-state, dest=0x8006cea8(MYTEST), job=0x80074a78(129), text="Job #%d started.", ...)
   219  D [18/Jul/2007:22:20:47 +0200] Discarding unused job-state event...
   220  D [18/Jul/2007:22:20:47 +0200] [Job 129] File 1 is complete.
   221  d [18/Jul/2007:22:20:47 +0200] cupsdFinishJob: job->status is 0
   222  d [18/Jul/2007:22:20:47 +0200] cupsdFinishJob: Removing fd 11 from InputSet...
   223  d [18/Jul/2007:22:20:47 +0200] cupsdFinishJob: Closing status pipes [ 11 -1 ]...
   224  d [18/Jul/2007:22:20:47 +0200] cupsdCancelJob: id = 129
   225  d [18/Jul/2007:22:20:47 +0200] cupsdStopJob: id = 129, force = 0
   226  d [18/Jul/2007:22:20:47 +0200] cupsdAddEvent(event=printer-state-changed, dest=0x8006cea8(MYTEST), job=(nil)(0), text="%s "%s" state changed.", ...)
   227  D [18/Jul/2007:22:20:47 +0200] Discarding unused printer-state-changed event...
   228  d [18/Jul/2007:22:20:47 +0200] cupsdStopJob: Closing print pipes [ -1 -1 ]...
   229  d [18/Jul/2007:22:20:47 +0200] cupsdStopJob: Closing back pipes [ -1 -1 ]...
   230  d [18/Jul/2007:22:20:47 +0200] cupsdAddEvent(event=job-completed, dest=0x8006cea8(MYTEST), job=0x80074a78(129), text="Job completed.", ...)
   231  D [18/Jul/2007:22:20:47 +0200] Discarding unused job-completed event...
   232  d [18/Jul/2007:22:20:47 +0200] cupsdSaveJob(job=0x80074a78(129)): job->attrs=0x800739e0
   233  d [18/Jul/2007:22:20:47 +0200] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
   234  D [18/Jul/2007:22:20:48 +0200] Unloading job 129...
   235  d [18/Jul/2007:22:20:48 +0200] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
   236  d [18/Jul/2007:22:20:48 +0200] select_timeout: 22 seconds to send browse update
   237  d [18/Jul/2007:22:21:10 +0200] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0
   238  d [18/Jul/2007:22:21:10 +0200] stringpool: 725 strings, 7320 allocated, 12984 total bytes
   239  d [18/Jul/2007:22:21:10 +0200] select_timeout: 5 seconds to send browse update


The lp command was: lp -d MYTEST /etc/passwd /etc/group
In Line 150 you can see the backend call but no one after the line 212!

Mario





More information about the cups mailing list