CUPS craps

Hogyan lehet két perc alatt több napos hibakeresést csinálni CUPS alatt?
Kell hozzá egy PC, két USB nyomtató, és a CUPS nevezetű ipari hulladék. Első lépésként csatlakoztassuk a nyomtatókat és kapcsoljuk be. Telepítsük a CUPSban mindkettőt és állítsuk be az egyiket alapértelmezett nyomtatóként. Nyomtassuk ki a tesztoldalakat. Örüljünk. Kapcsoljuk ki a számítógépet és a nyomtatókat, majd pár nap múlva kapcsoljuk be, és kapcsoljuk be azt a nyomtatót, amelyik nem az alapértelmezett.
Próbáljunk nyomtatni valamit, de nyomtatóként az alapértelmezett nyomtatót használjuk. Próbáljunk nyomtatni valamit a nem alapértelmezett nyomtatóra. A nyomtatás elindul és kis idő műlva "Unable send data to printer" hibaüzenettel megáll, a nyomtató Paused módba kerül és Resume Printer-re sem hajlandó a nyomtatás folytatni. Függetlenül mivel és hogyan próbálkozunk nyomtatni a hiba ugyanaz lesz.
dmesg-et megnézve ilyen szépségeket fogunk látni: 


[ 1011.586214] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 1013.305372] usblp0: removed
[ 1013.319910] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 1251.757315] usblp0: removed
[ 1314.595655] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4268.295899] usblp0: removed
[ 4268.309545] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4273.799281] usblp0: removed
[ 4273.813451] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4279.342722] usblp0: removed
[ 4279.356950] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4284.646289] usblp0: removed
[ 4284.660189] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4290.077973] usblp0: removed
[ 4290.092037] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4295.585363] usblp0: removed
[ 4295.599516] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4301.116841] usblp0: removed
[ 4301.130880] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
[ 4306.612244] usblp0: removed

Az lpr.logban ilyeneket találhatunk: 


Jun 15 10:22:19 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:19 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:19 toons udev-configure-printer: Device already handled
Jun 15 10:22:24 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:24 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:24 toons udev-configure-printer: Device already handled
Jun 15 10:22:30 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:30 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:30 toons udev-configure-printer: Device already handled
Jun 15 10:22:35 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:35 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:35 toons udev-configure-printer: Device already handled
Jun 15 10:22:41 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:41 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:41 toons udev-configure-printer: Device already handled
Jun 15 10:22:46 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:46 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:46 toons udev-configure-printer: Device already handled
Jun 15 10:22:52 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:52 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:52 toons udev-configure-printer: Device already handled
Jun 15 10:22:57 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 10:22:57 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 10:22:57 toons udev-configure-printer: Device already handled
Jun 15 11:07:53 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 11:07:53 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 11:07:53 toons udev-configure-printer: Device already handled

A syslog már valamivel többet mond: 


Jun 15 09:51:43 toons kernel: [ 4301.116841] usblp0: removed
Jun 15 09:51:43 toons kernel: [ 4301.130880] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
Jun 15 09:51:43 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 09:51:43 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 09:51:43 toons udev-configure-printer: Device already handled
Jun 15 09:51:48 toons kernel: [ 4306.612244] usblp0: removed
Jun 15 09:51:48 toons kernel: [ 4306.625968] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
Jun 15 09:51:48 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 09:51:48 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 09:51:48 toons udev-configure-printer: Device already handled
Jun 15 09:51:53 toons kernel: [ 4312.071542] usblp0: removed
Jun 15 09:51:53 toons kernel: [ 4312.085665] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
Jun 15 09:51:53 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 09:51:53 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 09:51:53 toons udev-configure-printer: Device already handled
Jun 15 09:51:59 toons kernel: [ 4317.538809] usblp0: removed
Jun 15 09:51:59 toons kernel: [ 4317.552822] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
Jun 15 09:51:59 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 09:51:59 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 09:51:59 toons udev-configure-printer: Device already handled
Jun 15 09:52:04 toons kernel: [ 4323.070542] usblp0: removed
Jun 15 09:52:04 toons kernel: [ 4323.084540] usblp 8-1.3:1.0: usblp0: USB Bidirectional printer dev 6 if 0 alt 0 proto 2 vid 0x04A9 pid 0x10C1
Jun 15 09:52:04 toons udev-configure-printer: add /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3/8-1.3:1.0/usbmisc/lp0
Jun 15 09:52:04 toons udev-configure-printer: device devpath is /devices/pci0000:00/0000:00:10.1/usb8/8-1/8-1.3
Jun 15 09:52:04 toons udev-configure-printer: Device already handled

Ha elindítunk egy top-ot, periodikusan megjelenik egy usb nevű processz egy-egy pillanatra 50-100%-os terhelést okoz, ha a PID-jére rákeresünk, valami ilyent fogunk látni: 


 usb://Lexmark/E260?serial=72LXW9G 323 boreger 61Vmb60.jpg (JPEG Image, 576??????792 pixels) - Scaled (94%) 1 TonerDarkness=PrinterS GrayCorrection=PrinterS OutputBin=PrinterS number-up=1 PageSize=A4 Resolution=600dpi InputSlot=Tray1 LexContrast=PrinterS LexBrightness=PrinterS LexPixelBoost=PrinterS LexBlankPage=PrinterS MediaType=PrinterS SepSource=PrinterS LexLineDetail=PrinterS SepPages=PrinterS job-uuid=urn:uuid:13223acb-5dae-3e46-7e8d-aa3c218a7641 job-originating-host-name=localhost time-at-creation=1402820456 time-at-processing=1402820456

Ez utóbbi a CUPS periodikus próbálkozása, hogy az inaktív alapértelmezett nyomtatóra nyomtasson. Ha kilőjük a nyomtatási sorból a munkát, akkor eltűnik a processz és csodák csodája, jó lesz a nem alapértelmezett nyomtató.
Mi lehet a hiba? Sanda gyanúm, hogy a CUPSnak az alapértelmezett nyomtató pollingolásakor, az udev izomból eltávolítja a meglévő nyomtatót, függetlenül attól, hogy annak mi az állapota, majd újrakonfigurálja. Hogy most ez kinek a hibája, azt nyomozza akinek hat anyja volt, mert sanda gyanúm, hogy a tipikus, koncepciótlan, mindent nyolcféleképp, egymással szembemenve oldunk meg mentalitás újabb gyönyörű példájával állunk szemben.

( hrgy84 | 2014. 06. 16., h – 10:25 )

"a tipikus, koncepciótlan, mindent nyolcféleképp, egymással szembemenve oldunk meg mentalitás újabb gyönyörű példájával állunk szemben."

Welcome in the opensource world.
-- 

Ki oda vagyik, hol szall a galamb, elszalasztja a kincset itt alant.

( XMI | 2014. 06. 23., h – 00:20 )

a CUPSnak az alapértelmezett nyomtató pollingolásakor, az udev izomból eltávolítja a meglévő nyomtatót, függetlenül attól, hogy annak mi az állapota, majd újrakonfigurálja.
Hótziher, hogy ez valami más bugnak a workaroundja miatt lett ilyen.
---
Régóta vágyok én, az androidok mezonkincsére már!