Bug#1025475: cups-tea4cups: The script is very slow. it takes about 20 seconds more.

[Miquel Gual Torner]

Package: cups-tea4cups
Version: 3.14~alpha0+svn3576-2
Severity: normal

Dear Maintainer,

*** Reporter, please consider answering these questions, where appropriate ***

* What led up to the situation?

I have upgraded to debian bullseye version (tea4cups 3.15alpha_unofficial) and before we had debian stretch (tea4cups 3.13alpha_unofficial).

* What exactly did you do (or not do) that was effective (or

ineffective)?

tea4cups 3.15alpha_unofficial -> más de 10 segundos
tea4cups 3.13alpha_unofficial -> más de 2 segundos

Instalar version 3.13alpha_unofficial
* Instalar python2
* Instalar version de tea4cups 3.13alpha_unofficial
* modificar cabezera tea4cups

* What was the outcome of this action?
* What outcome did you expect instead?

*** End of the template - remove these template lines ***


-- System Information:
Debian Release: 11.5
APT prefers stable-security
APT policy: (500, 'stable-security'), (500, 'stable')
Architecture: amd64 (x86_64)

Kernel: Linux 5.13.19-1-pve (SMP w/4 CPU threads)
Kernel taint flags: TAINT_PROPRIETARY_MODULE, TAINT_FIRMWARE_WORKAROUND, TAINT_OOT_MODULE
Locale: LANG=ca_ES.UTF-8, LC_CTYPE=ca_ES.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to ca_ES.UTF-8), LANGUAGE=ca_ES.UTF-8
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages cups-tea4cups depends on:
ii cups 2.3.3op2-3+deb11u2
ii python3 3.9.2-3

cups-tea4cups recommends no packages.

cups-tea4cups suggests no packages.

-- Configuration Files:
/etc/cups/tea4cups.conf changed:
[global]
debug : yes
directory : /var/spool/cups/
[ip003_1c]
posthook_ip003_1c : lp -d ip003_ppd -o media=a4 -o sides=one-sided -U $TEAUSERNAME $TEADATAFILE
[ip003_2c]
posthook_ip003_2c : cat $TEADATAFILE | /usr/local/bin/filter-ps-duplex | lp -d ip003_ppd -o media=a4 -o sides=two-sided-long-edge -U $TEAUSERNAME

-- no debconf information

---- tea4cups 3.15alpha_unofficial -----

/tmp/file_cups_env ; time python3 /usr/lib/cups/backend/tea4cups 12246 mgual "Test Page" 1 "job-uuid=urn:uuid:4aea244a-5d88-309f-4523-6109e83d0a83 date-time-at-creation= date-time-at-processing= time-at-creation=1670220463 time-at-processing=1670220463" /tmp/file_cups

DEBUG:root:Not attached to an existing print queue.
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : Not attached to an existing print queue.
DEBUG:root:charset is set to [('charset', 'utf-8')]
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : charset is set to [('charset', 'utf-8')]
DEBUG:root:language is set to [('naturalLanguage', 'en-us')]
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : language is set to [('naturalLanguage', 'en-us')]
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): localhost:631
DEBUG:urllib3.connectionpool:http://localhost:631 "POST / HTTP/1.1" 400 379
DEBUG:root:data to parse: <urllib3.response.HTTPResponse object at 0x7f9257df26d0>
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : data to parse: <urllib3.response.HTTPResponse object at 0x7f9257df26d0>
DEBUG:root:Parsing of IPP message file /var/spool/cups/c12246 begins.
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : Parsing of IPP message file /var/spool/cups/c12246 begins.
Tea4CUPS (PID 4943) : ERROR: Tea4CUPS v3.15alpha_unofficial
ERROR: Tea4CUPS (PID 4943) : Traceback (most recent call last):
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1177, in initBackend
ERROR: Tea4CUPS (PID 4943) :     answer = cupsserver.getJobAttributes(self.JobId)
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 784, in getJobAttributes
ERROR: Tea4CUPS (PID 4943) :     return self.doRequest(req)
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 762, in doRequest
ERROR: Tea4CUPS (PID 4943) :     wrapper.logDebug("request content: %s"%str(r.raw.content))
ERROR: Tea4CUPS (PID 4943) : AttributeError: 'HTTPResponse' object has no attribute 'content'
ERROR: Tea4CUPS (PID 4943) : During handling of the above exception, another exception occurred:
ERROR: Tea4CUPS (PID 4943) : Traceback (most recent call last):
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1547, in <module>
ERROR: Tea4CUPS (PID 4943) :     wrapper.initBackend()
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1183, in initBackend
ERROR: Tea4CUPS (PID 4943) :     (ippfilename, answer) = self.parseIPPRequestFile()
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1233, in parseIPPRequestFile
ERROR: Tea4CUPS (PID 4943) :     ippmessage = IPPRequest(ippdatafile.read())
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/python3.9/codecs.py", line 322, in decode
ERROR: Tea4CUPS (PID 4943) :     (result, consumed) = self._buffer_decode(data, self.errors, final)
ERROR: Tea4CUPS (PID 4943) : UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe6 in position 443: invalid continuation byte
DEBUG:root:Tea4CUPS (PID 4943) : ERROR: Tea4CUPS v3.15alpha_unofficial
ERROR: Tea4CUPS (PID 4943) : Traceback (most recent call last):
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1177, in initBackend
ERROR: Tea4CUPS (PID 4943) :     answer = cupsserver.getJobAttributes(self.JobId)
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 784, in getJobAttributes
ERROR: Tea4CUPS (PID 4943) :     return self.doRequest(req)
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 762, in doRequest
ERROR: Tea4CUPS (PID 4943) :     wrapper.logDebug("request content: %s"%str(r.raw.content))
ERROR: Tea4CUPS (PID 4943) : AttributeError: 'HTTPResponse' object has no attribute 'content'
ERROR: Tea4CUPS (PID 4943) : During handling of the above exception, another exception occurred:
ERROR: Tea4CUPS (PID 4943) : Traceback (most recent call last):
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1547, in <module>
ERROR: Tea4CUPS (PID 4943) :     wrapper.initBackend()
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1183, in initBackend
ERROR: Tea4CUPS (PID 4943) :     (ippfilename, answer) = self.parseIPPRequestFile()
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1233, in parseIPPRequestFile
ERROR: Tea4CUPS (PID 4943) :     ippmessage = IPPRequest(ippdatafile.read())
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/python3.9/codecs.py", line 322, in decode
ERROR: Tea4CUPS (PID 4943) :     (result, consumed) = self._buffer_decode(data, self.errors, final)
ERROR: Tea4CUPS (PID 4943) : UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe6 in position 443: invalid continuation byte

[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : Tea4CUPS (PID 4943) : ERROR: Tea4CUPS v3.15alpha_unofficial
ERROR: Tea4CUPS (PID 4943) : Traceback (most recent call last):
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1177, in initBackend
ERROR: Tea4CUPS (PID 4943) :     answer = cupsserver.getJobAttributes(self.JobId)
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 784, in getJobAttributes
ERROR: Tea4CUPS (PID 4943) :     return self.doRequest(req)
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 762, in doRequest
ERROR: Tea4CUPS (PID 4943) :     wrapper.logDebug("request content: %s"%str(r.raw.content))
ERROR: Tea4CUPS (PID 4943) : AttributeError: 'HTTPResponse' object has no attribute 'content'
ERROR: Tea4CUPS (PID 4943) : During handling of the above exception, another exception occurred:
ERROR: Tea4CUPS (PID 4943) : Traceback (most recent call last):
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1547, in <module>
ERROR: Tea4CUPS (PID 4943) :     wrapper.initBackend()
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1183, in initBackend
ERROR: Tea4CUPS (PID 4943) :     (ippfilename, answer) = self.parseIPPRequestFile()
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/cups/backend/tea4cups", line 1233, in parseIPPRequestFile
ERROR: Tea4CUPS (PID 4943) :     ippmessage = IPPRequest(ippdatafile.read())
ERROR: Tea4CUPS (PID 4943) :   File "/usr/lib/python3.9/codecs.py", line 322, in decode
ERROR: Tea4CUPS (PID 4943) :     (result, consumed) = self._buffer_decode(data, self.errors, final)
ERROR: Tea4CUPS (PID 4943) : UnicodeDecodeError: 'utf-8' codec can't decode byte 0xe6 in position 443: invalid continuation byte

DEBUG:root:Cleaning up...
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : Cleaning up...
DEBUG:root:Clean.
[TEA4CUPS]_DEBUG: Tea4CUPS v3.15alpha_unofficial (PID 4943) : Clean.

real    0m10,175s
user    0m0,144s
sys     0m0,020s

---- tea4cups 3.13alpha_unofficial -----

root@cups-ajt-server-stretch:/# . /tmp/cups-env ; time python2 /usr/lib/cups/backend/tea4cups 12246 mgual "Test Page" 1 "job-uuid=urn:uuid:4aea244a-5d88-309f-4523-6109e83d0a83 date-time-at-creation= date-time-at-processing= time-at-creation=1670220463 time-at-processing=1670220463" /tmp/file_cups
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Not attached to an existing print queue.
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Waiting for lock /var/spool/cups/tea4cups-..LCK to become available...
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Lock /var/spool/cups/tea4cups-..LCK acquired.
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Duplicating data stream into /var/spool/cups/tea4cups-ip002_1c-mgual-12246
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Data stream will be used as-is (no filter defined)
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : 4 bytes saved...
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : 4 bytes saved...
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Job 12246 is 4 bytes long.
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Job 12246 MD5 sum is 5c9597f3c8245907ea71a89d9d39d08e
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Begin forked Prehooks
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : End forked Prehooks
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Begin forked Posthooks
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 632) : Launching posthook_ip002_1c : lp -d ip002_ppd -o media=a4 -o sides=one-sided -U $TEAUSERNAME $TEADATAFILE
l'identificador de la petició és ip002_ppd-2079707 (1 fitxer(s))
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Exit code for posthook posthook_ip002_1c (PID 632) on printer ip002_1c is 0
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : End forked Posthooks
INFO: Tea4CUPS v3.13alpha_unofficial (PID 631) : OK
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Cleaning up...
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Removing lock...
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Lock removed.
DEBUG: Tea4CUPS v3.13alpha_unofficial (PID 631) : Clean.

real    0m0,060s
user    0m0,048s
sys     0m0,003s