Binary package hint: cupsys
when printing from Evince or directly from Firefox, HP laserjet 1160 only prints the top of the page. Then a couple of strange marks and the rest of the page is empty. Disabling AppArmor seems to help (the audit message in the end)
The task is left to the printer queue after that.
kex@xpc:/var/log$ lsb_release -rd
Description: Ubuntu 8.04
Release: 8.04
kex@xpc:/var/log$ echo $LANG
fi_FI.UTF-8
kex@xpc:/var/log$ sudo lsmod | grep lp
lp 12324 0
parport 37832 3 ppdev,lp,parport_pc
kex@xpc:/var/log$ dmesg | grep par
[ 26.354683] Booting paravirtualized kernel on bare hardware
[ 26.379364] PCI: Transparent bridge - 0000:00:1e.0
[ 40.417804] parport_pc 00:09: reported by Plug and Play ACPI
[ 40.417857] parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
[ 44.391942] lp0: using parport0 (interrupt-driven).
[ 49.777335] ppdev: user-space parallel port driver
[ 2983.189775] ppdev0: registered pardevice
[ 2985.788588] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 2985.788873] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 2985.788922] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 2985.788951] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 2985.789178] ppdev0: registered pardevice
[ 3074.857787] ppdev0: unregistered pardevice
[ 3074.861881] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 3074.862140] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 3074.862183] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 3074.862215] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 3074.862427] ppdev0: registered pardevice
[ 3074.899370] ppdev0: released pardevice because user-space forgot
[ 3074.899379] ppdev0: unregistered pardevice
[ 3076.311090] ppdev0: registered pardevice
[ 3162.781738] ppdev0: unregistered pardevice
[ 3162.814209] ppdev0: released pardevice because user-space forgot
[ 3162.814215] ppdev0: unregistered pardevice
[ 3162.827294] ppdev0: registered pardevice
[ 3163.795724] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 3163.795977] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 3163.796021] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 3163.796048] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 3163.796230] ppdev0: registered pardevice
[ 3222.011748] ppdev0: unregistered pardevice
[ 3222.016295] ppdev0: released pardevice because user-space forgot
[ 3222.016841] ppdev0: unregistered pardevice
[ 4081.504891] ppdev0: registered pardevice
[ 4082.291770] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 4082.291991] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 4082.292026] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 4082.292050] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 4082.292217] ppdev0: registered pardevice
[ 4099.266124] ppdev0: unregistered pardevice
[ 4310.369063] ppdev0: released pardevice because user-space forgot
[ 4310.369885] ppdev0: unregistered pardevice
[ 4310.388166] ppdev0: registered pardevice
[ 4311.068017] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 4311.068235] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 4311.068287] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 4311.068311] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 4311.068478] ppdev0: registered pardevice
[ 4326.644304] ppdev0: unregistered pardevice
[ 4337.569256] ppdev0: unregistered pardevice
[ 5889.958768] ppdev0: registered pardevice
[ 5889.958794] ppdev0: unregistered pardevice
[ 5890.575803] ppdev0: registered pardevice
[ 5890.586387] ppdev0: unregistered pardevice
[ 6048.228815] ppdev0: registered pardevice
[ 6048.968134] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 6048.968414] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 6048.968470] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 6048.968502] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 6048.968724] ppdev0: registered pardevice
[ 6202.008296] ppdev0: unregistered pardevice
[ 6202.047474] ppdev0: released pardevice because user-space forgot
[ 6202.049677] ppdev0: unregistered pardevice
[ 6203.006368] ppdev0: registered pardevice
[ 6203.855278] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 6203.855500] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 6203.855549] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 6203.855574] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 6203.855745] ppdev0: registered pardevice
[ 6234.143923] ppdev0: unregistered pardevice
[ 6245.137444] ppdev0: unregistered pardevice
[ 6339.387015] ppdev0: registered pardevice
[ 6340.257484] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 6340.257774] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 6340.257822] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 6340.257851] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 6340.258074] ppdev0: registered pardevice
[ 6446.448463] ppdev0: released pardevice because user-space forgot
[ 6446.449233] ppdev0: unregistered pardevice
[ 6446.500801] ppdev0: unregistered pardevice
[ 6446.532073] ppdev0: registered pardevice
[ 6447.368576] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 6447.368797] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 6447.368834] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 6447.368859] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 6447.369029] ppdev0: registered pardevice
[ 6659.854473] ppdev0: released pardevice because user-space forgot
[ 6659.855265] ppdev0: unregistered pardevice
[ 6659.886853] ppdev0: unregistered pardevice
[ 6673.781911] ppdev0: registered pardevice
[ 6674.896031] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 6674.896321] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 6674.896370] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 6674.896400] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 6674.896623] ppdev0: registered pardevice
[ 6765.095026] ppdev0: unregistered pardevice
[ 6765.099407] ppdev0: released pardevice because user-space forgot
[ 6765.100158] ppdev0: unregistered pardevice
[ 6780.586337] ppdev0: registered pardevice
[ 6781.527504] sysctl table check failed: /dev/parport/parport0/devices/ppdev0/timeslice Sysctl already exists
[ 6781.527785] [<c0132a59>] sysctl_set_parent+0x19/0x30
[ 6781.527833] [<f8a0a90e>] parport_device_proc_register+0xae/0xe0 [parport]
[ 6781.527865] [<f8a08e29>] parport_register_device+0x139/0x260 [parport]
[ 6781.528085] ppdev0: registered pardevice
[ 6814.711283] ppdev0: unregistered pardevice
[ 6825.817594] ppdev0: unregistered pardevice
kex@xpc:/var/log$ lpinfo -v
network socket
network beh
direct hal
direct hpfax
direct parallel:/dev/lp0
direct hp:/par/hp_LaserJet_1160_series?device=/dev/parport0
network http
network ipp
network lpd
file cups-pdf:/
direct scsi
network smb
***********
/var/log/cupsys/error_log
D [27/Apr/2008:10:55:59 +0300] cupsdAcceptClient: 8 from localhost (Domain)
D [27/Apr/2008:10:55:59 +0300] Report: clients=1
D [27/Apr/2008:10:55:59 +0300] Report: jobs=69
D [27/Apr/2008:10:55:59 +0300] Report: jobs-active=0
D [27/Apr/2008:10:55:59 +0300] Report: printers=2
D [27/Apr/2008:10:55:59 +0300] Report: printers-implicit=0
D [27/Apr/2008:10:55:59 +0300] Report: stringpool-string-count=693
D [27/Apr/2008:10:55:59 +0300] Report: stringpool-alloc-bytes=8392
D [27/Apr/2008:10:55:59 +0300] Report: stringpool-total-bytes=13072
D [27/Apr/2008:10:55:59 +0300] cupsdReadClient: 8 POST / HTTP/1.1
D [27/Apr/2008:10:55:59 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:55:59 +0300] CUPS-Get-Default
D [27/Apr/2008:10:55:59 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:55:59 +0300] cupsdAcceptClient: 11 from localhost (Domain)
D [27/Apr/2008:10:55:59 +0300] cupsdCloseClient: 8
D [27/Apr/2008:10:55:59 +0300] cupsdReadClient: 11 POST / HTTP/1.1
D [27/Apr/2008:10:55:59 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:55:59 +0300] CUPS-Get-Printers
D [27/Apr/2008:10:55:59 +0300] cupsdProcessIPPRequest: 11 status_code=0 (successful-ok)
D [27/Apr/2008:10:55:59 +0300] cupsdAcceptClient: 8 from localhost:631 (IPv4)
D [27/Apr/2008:10:55:59 +0300] cupsdCloseClient: 11
D [27/Apr/2008:10:55:59 +0300] cupsdReadClient: 8 GET /printers/hp_LaserJet_1160_series.ppd HTTP/1.1
D [27/Apr/2008:10:55:59 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:55:59 +0300] cupsdCloseClient: 8
D [27/Apr/2008:10:56:02 +0300] cupsdAcceptClient: 8 from localhost (Domain)
D [27/Apr/2008:10:56:02 +0300] cupsdReadClient: 8 POST /printers/hp_LaserJet_1160_series HTTP/1.1
D [27/Apr/2008:10:56:02 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:02 +0300] Print-Job ipp://localhost:631/printers/hp_LaserJet_1160_series
D [27/Apr/2008:10:56:02 +0300] print_job: auto-typing file...
D [27/Apr/2008:10:56:02 +0300] add_job: requesting-user-name="kex"
I [27/Apr/2008:10:56:02 +0300] [Job 70] Adding start banner page "none".
D [27/Apr/2008:10:56:02 +0300] Discarding unused job-created event...
I [27/Apr/2008:10:56:02 +0300] [Job 70] Adding job file of type application/postscript.
I [27/Apr/2008:10:56:02 +0300] [Job 70] Adding end banner page "none".
I [27/Apr/2008:10:56:02 +0300] [Job 70] Queued on "hp_LaserJet_1160_series" by "kex".
D [27/Apr/2008:10:56:02 +0300] [Job 70] hold_until = 0
D [27/Apr/2008:10:56:02 +0300] Discarding unused printer-state-changed event...
D [27/Apr/2008:10:56:02 +0300] [Job 70] job-sheets=none,none
D [27/Apr/2008:10:56:02 +0300] [Job 70] banner_page = 0
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[0]="hp_LaserJet_1160_series"
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[1]="70"
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[2]="kex"
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[3]="evince-print"
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[4]="1"
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[5]="PrintoutMode=Normal PageSize=A4 Quality=FromPrintoutMode Duplex=None InputSlot=Default number-up=1 job-uuid=urn:uuid:d3dc23b0-eca5-3801-7ed3-a69c1a8e4ba4"
D [27/Apr/2008:10:56:02 +0300] [Job 70] argv[6]="/var/spool/cups/d00070-001"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[0]="CUPS_CACHEDIR=/var/cache/cups"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[1]="CUPS_DATADIR=/usr/share/cups"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[2]="CUPS_DOCROOT=/usr/share/cups/doc-root"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[3]="CUPS_FONTPATH=/usr/share/cups/fonts"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[4]="CUPS_REQUESTROOT=/var/spool/cups"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[5]="CUPS_SERVERBIN=/usr/lib/cups"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[6]="CUPS_SERVERROOT=/etc/cups"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[7]="CUPS_STATEDIR=/var/run/cups"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[8]="PATH=/usr/lib/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[9]="SERVER_ADMIN=root@xpc"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[10]="SOFTWARE=CUPS/1.3.7"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[11]="TMPDIR=/var/spool/cups/tmp"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[12]="TZ=Europe/Helsinki"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[13]="USER=root"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[14]="CUPS_SERVER=/var/run/cups/cups.sock"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[15]="CUPS_ENCRYPTION=IfRequested"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[16]="IPP_PORT=631"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[17]="CHARSET=utf-8"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[18]="LANG=fi_FI.UTF8"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[19]="PPD=/etc/cups/ppd/hp_LaserJet_1160_series.ppd"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[20]="RIP_MAX_CACHE=8m"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[21]="CONTENT_TYPE=application/postscript"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[22]="DEVICE_URI=hp:/par/hp_LaserJet_1160_series?device=/dev/parport0"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[23]="PRINTER=hp_LaserJet_1160_series"
D [27/Apr/2008:10:56:02 +0300] [Job 70] envp[24]="FINAL_CONTENT_TYPE=printer/hp_LaserJet_1160_series"
I [27/Apr/2008:10:56:02 +0300] [Job 70] Started filter /usr/lib/cups/filter/pstops (PID 10823)
I [27/Apr/2008:10:56:02 +0300] [Job 70] Started filter /usr/lib/cups/filter/foomatic-rip (PID 10825)
I [27/Apr/2008:10:56:02 +0300] [Job 70] Started backend /usr/lib/cups/backend/hp (PID 10826)
D [27/Apr/2008:10:56:02 +0300] Discarding unused job-state-changed event...
D [27/Apr/2008:10:56:02 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:02 +0300] cupsdAcceptClient: 11 from localhost (Domain)
D [27/Apr/2008:10:56:02 +0300] Discarding unused printer-state-changed event...
D [27/Apr/2008:10:56:02 +0300] cupsdReadClient: 11 POST / HTTP/1.1
D [27/Apr/2008:10:56:02 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:02 +0300] Get-Jobs ipp://localhost/jobs/
D [27/Apr/2008:10:56:02 +0300] cupsdProcessIPPRequest: 11 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:02 +0300] [Job 70] prnt/backend/hp.c 496: unable to connect hpssd socket 2207: Connection refused
D [27/Apr/2008:10:56:02 +0300] cupsdReadClient: 11 POST / HTTP/1.1
D [27/Apr/2008:10:56:02 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:02 +0300] CUPS-Get-Printers
D [27/Apr/2008:10:56:02 +0300] cupsdProcessIPPRequest: 11 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:02 +0300] [Job 70] Page = 595x842; 18,14 to 577,828
D [27/Apr/2008:10:56:02 +0300] [Job 70] slow_collate=0, slow_duplex=0, slow_order=0
D [27/Apr/2008:10:56:02 +0300] [Job 70] Before copy_comments - %!PS-Adobe-3.0
D [27/Apr/2008:10:56:02 +0300] [Job 70] %!PS-Adobe-3.0
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%Creator: cairo 1.6.0 (http://cairographics.org)
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%CreationDate: Sun Apr 27 10:56:02 2008
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%Pages: 1
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%BoundingBox: 0 0 596 842
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%DocumentData: Clean7Bit
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%LanguageLevel: 2
D [27/Apr/2008:10:56:02 +0300] [Job 70] %%EndComments
D [27/Apr/2008:10:56:02 +0300] [Job 70] Before copy_prolog - %%BeginProlog
D [27/Apr/2008:10:56:02 +0300] [Job 70] Before copy_setup - 11 dict begin
D [27/Apr/2008:10:56:02 +0300] [Job 70] Before page loop - %%Page: 1 1
D [27/Apr/2008:10:56:02 +0300] [Job 70] Copying page 1...
D [27/Apr/2008:10:56:02 +0300] [Job 70] pagew = 559.0, pagel = 813.2
D [27/Apr/2008:10:56:02 +0300] [Job 70] bboxx = 0, bboxy = 0, bboxw = 595, bboxl = 842
D [27/Apr/2008:10:56:02 +0300] [Job 70] PageLeft = 18.0, PageRight = 577.0
D [27/Apr/2008:10:56:02 +0300] [Job 70] PageTop = 827.6, PageBottom = 14.4
D [27/Apr/2008:10:56:02 +0300] [Job 70] PageWidth = 595.0, PageLength = 842.0
D [27/Apr/2008:10:56:02 +0300] cupsdCloseClient: 8
D [27/Apr/2008:10:56:02 +0300] cupsdCloseClient: 11
D [27/Apr/2008:10:56:02 +0300] [Job 70] foomatic-rip version $Revision$ running...
D [27/Apr/2008:10:56:02 +0300] [Job 70] Parsing PPD file ...
D [27/Apr/2008:10:56:02 +0300] [Job 70] *cupsFilter: "application/vnd.cups-postscript 0 foomatic-rip"
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option ColorSpace
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option Resolution
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option PageSize
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option PageRegion
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option Model
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option PrintoutMode
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option InputSlot
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option ImageableArea
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option PaperDimension
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option Duplex
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option Quality
D [27/Apr/2008:10:56:02 +0300] [Job 70] Added option Font
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] Parameter Summary
D [27/Apr/2008:10:56:02 +0300] [Job 70] -----------------
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] Spooler: cups
D [27/Apr/2008:10:56:02 +0300] [Job 70] Printer: hp_LaserJet_1160_series
D [27/Apr/2008:10:56:02 +0300] [Job 70] Shell: /bin/bash
D [27/Apr/2008:10:56:02 +0300] [Job 70] PPD file: /etc/cups/ppd/hp_LaserJet_1160_series.ppd
D [27/Apr/2008:10:56:02 +0300] [Job 70] ATTR file:
D [27/Apr/2008:10:56:02 +0300] [Job 70] Printer model: HP LaserJet 1160 Foomatic/hpijs (recommended)
D [27/Apr/2008:10:56:02 +0300] [Job 70] Job title: evince-print
D [27/Apr/2008:10:56:02 +0300] [Job 70] File(s) to be printed:
D [27/Apr/2008:10:56:02 +0300] [Job 70] <STDIN>
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] GhostScript extra search path ('GS_LIB'): /usr/share/cups/fonts
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'PrintoutMode=Normal'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'PageSize=A4'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'Quality=FromPrintoutMode'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'Duplex=None'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'InputSlot=Default'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'number-up=1'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Unknown option number-up=1.
D [27/Apr/2008:10:56:02 +0300] [Job 70] Pondering option 'job-uuid=urn:uuid:d3dc23b0-eca5-3801-7ed3-a69c1a8e4ba4'
D [27/Apr/2008:10:56:02 +0300] [Job 70] Unknown option job-uuid=urn:uuid:d3dc23b0-eca5-3801-7ed3-a69c1a8e4ba4.
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] ================================================
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] File: <STDIN>
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] ================================================
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] Reading PostScript input ...
D [27/Apr/2008:10:56:02 +0300] [Job 70] --> This document is DSC-conforming!
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] -----------
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginProlog
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%EndProlog
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] -----------
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginSetup
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginFeature: *PrintoutMode Normal
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: PrintoutMode=Normal --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %% FoomaticRIPOptionSetting: PrintoutMode=Normal
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: PrintoutMode=Normal --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginFeature: *InputSlot Default
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: InputSlot=Default --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %% FoomaticRIPOptionSetting: InputSlot=Default
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: InputSlot=Default --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginFeature: *Quality FromPrintoutMode
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: Quality=FromPrintoutMode --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %% FoomaticRIPOptionSetting: Quality=@PrintoutMode
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: Quality=FromPrintoutMode --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginFeature: *PageRegion A4
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: PageRegion=A4 --> Option will be set by PostScript interpreter
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %% FoomaticRIPOptionSetting: PageSize=A4
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: PageSize=A4 --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginFeature: *Duplex None
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: Duplex=None --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %% FoomaticRIPOptionSetting: Duplex=None
D [27/Apr/2008:10:56:02 +0300] [Job 70] Option: Duplex=None --> Setting option
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%EndSetup
D [27/Apr/2008:10:56:02 +0300] [Job 70] Inserting PostScript code for CUPS' page accounting
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] -----------
D [27/Apr/2008:10:56:02 +0300] [Job 70] New page: 1 1
D [27/Apr/2008:10:56:02 +0300] [Job 70] Inserting option code into "PageSetup" section.
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%BeginPageSetup
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: %%EndPageSetup
D [27/Apr/2008:10:56:02 +0300] [Job 70] End of page header
D [27/Apr/2008:10:56:02 +0300] [Job 70] Stopping search for page header options
D [27/Apr/2008:10:56:02 +0300] [Job 70] Found: 198.562 476.32 l 196.602 476.32 l 196.602 448.555 l 204.391 448.555 l
D [27/Apr/2008:10:56:02 +0300] [Job 70] --> Output goes directly to the renderer now.
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] Starting renderer
D [27/Apr/2008:10:56:02 +0300] [Job 70] JCL: <job data>
D [27/Apr/2008:10:56:02 +0300] [Job 70]
D [27/Apr/2008:10:56:02 +0300] [Job 70] renderer PID kid4=10834
D [27/Apr/2008:10:56:02 +0300] [Job 70] renderer command: gs -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=ijs -sIjsServer=hpijs -sDeviceManufacturer="HEWLETT-PACKARD" -sDeviceModel="HP LaserJet" -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dDuplex=false -r300 -sIjsParams=Quality:Quality=0,Quality:ColorMode=0,Quality:MediaType=0,Quality:PenSet=0,PS:MediaPosition=7 -dIjsUseOutputFD -sOutputFile=- -
D [27/Apr/2008:10:56:02 +0300] [Job 70] Starting process 10835: "foomatic-gswrapper -q -dBATCH -dPARANOIDSAFER -dQUIET -dNOPAUSE -sDEVICE=ijs -sIjsServer=hpijs -sDev..."
D [27/Apr/2008:10:56:02 +0300] [Job 70] foomatic-gswrapper: gs '-sstdout=%stderr' '-dBATCH' '-dPARANOIDSAFER' '-dQUIET' '-dNOPAUSE' '-sDEVICE=ijs' '-sIjsServer=hpijs' '-sDeviceManufacturer=HEWLETT-PACKARD' '-sDeviceModel=HP LaserJet' '-dDEVICEWIDTHPOINTS=595' '-dDEVICEHEIGHTPOINTS=842' '-dDuplex=false' '-r300' '-sIjsParams=Quality:Quality=0,Quality:ColorMode=0,Quality:MediaType=0,Quality:PenSet=0,PS:MediaPosition=7' '-dIjsUseOutputFD' '-sOutputFile=%stdout' '-_'
D [27/Apr/2008:10:56:03 +0300] cupsdAcceptClient: 8 from localhost (Domain)
D [27/Apr/2008:10:56:03 +0300] cupsdReadClient: 8 POST / HTTP/1.1
D [27/Apr/2008:10:56:03 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:03 +0300] Get-Jobs ipp://localhost/jobs/
D [27/Apr/2008:10:56:03 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:03 +0300] cupsdReadClient: 8 POST / HTTP/1.1
D [27/Apr/2008:10:56:03 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:03 +0300] CUPS-Get-Printers
D [27/Apr/2008:10:56:03 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:03 +0300] cupsdCloseClient: 8
D [27/Apr/2008:10:56:03 +0300] [Job 70] Wrote 1 pages...
D [27/Apr/2008:10:56:03 +0300] PID 10823 (/usr/lib/cups/filter/pstops) exited with no errors.
D [27/Apr/2008:10:56:03 +0300] [Job 70] Found: %%Trailer
D [27/Apr/2008:10:56:03 +0300] [Job 70] --> Continue DSC parsing now.
D [27/Apr/2008:10:56:03 +0300] [Job 70]
D [27/Apr/2008:10:56:03 +0300] [Job 70] Found: %%Pages: 1
D [27/Apr/2008:10:56:03 +0300] [Job 70] --> Continue DSC parsing now.
D [27/Apr/2008:10:56:03 +0300] [Job 70]
D [27/Apr/2008:10:56:03 +0300] [Job 70] Found: %%BoundingBox: 0 0 596 842
D [27/Apr/2008:10:56:03 +0300] [Job 70] --> Continue DSC parsing now.
D [27/Apr/2008:10:56:03 +0300] [Job 70]
D [27/Apr/2008:10:56:03 +0300] [Job 70] Found: %%EOF
D [27/Apr/2008:10:56:03 +0300] [Job 70] --> Continue DSC parsing now.
D [27/Apr/2008:10:56:03 +0300] [Job 70]
D [27/Apr/2008:10:56:03 +0300] [Job 70]
D [27/Apr/2008:10:56:03 +0300] [Job 70] Closing renderer
D [27/Apr/2008:10:56:03 +0300] Discarding unused job-progress event...
D [27/Apr/2008:10:56:03 +0300] Discarding unused printer-state-changed event...
D [27/Apr/2008:10:56:04 +0300] cupsdAcceptClient: 8 from localhost (Domain)
D [27/Apr/2008:10:56:04 +0300] cupsdReadClient: 8 POST / HTTP/1.1
D [27/Apr/2008:10:56:04 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:04 +0300] Get-Jobs ipp://localhost/jobs/
D [27/Apr/2008:10:56:04 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:04 +0300] cupsdReadClient: 8 POST / HTTP/1.1
D [27/Apr/2008:10:56:04 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:56:04 +0300] CUPS-Get-Printers
D [27/Apr/2008:10:56:04 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:56:04 +0300] cupsdCloseClient: 8
D [27/Apr/2008:10:57:00 +0300] Report: clients=0
D [27/Apr/2008:10:57:00 +0300] Report: jobs=70
D [27/Apr/2008:10:57:00 +0300] Report: jobs-active=1
D [27/Apr/2008:10:57:00 +0300] Report: printers=2
D [27/Apr/2008:10:57:00 +0300] Report: printers-implicit=0
D [27/Apr/2008:10:57:00 +0300] Report: stringpool-string-count=743
D [27/Apr/2008:10:57:00 +0300] Report: stringpool-alloc-bytes=9392
D [27/Apr/2008:10:57:00 +0300] Report: stringpool-total-bytes=14000
D [27/Apr/2008:10:57:02 +0300] cupsdAcceptClient: 8 from localhost (Domain)
D [27/Apr/2008:10:57:02 +0300] cupsdReadClient: 8 POST / HTTP/1.1
D [27/Apr/2008:10:57:02 +0300] cupsdAuthorize: No authentication data provided.
D [27/Apr/2008:10:57:02 +0300] CUPS-Get-Printers
D [27/Apr/2008:10:57:02 +0300] cupsdProcessIPPRequest: 8 status_code=0 (successful-ok)
D [27/Apr/2008:10:57:02 +0300] cupsdCloseClient: 8
***
/var/log/messages have these:
Apr 27 10:56:02 xpc kernel: [ 8697.305423] audit(1209282962.312:16): type=1503 operation="inode_permission" requested_mask="::rw" denied_mask="::rw" name="/dev/tty" pid=10832 profile="/usr/sbin/cupsd" namespace="default"
ah, I was too hasty. disabling AppArmor does not help - only the top of the page gets out :)