[cups-devel] [UNKN] STR #4586: Under load CUPS loses client connections with "A TLS packet with unexpected length was received."

Alex Korobkin noreply at cups.org
Thu Mar 12 14:45:15 PDT 2015


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

DO NOT REPLY TO THIS MESSAGE.  INSTEAD, POST ANY RESPONSES TO THE LINK BELOW.

[STR New]

We can probably rule out gnutls, because I compiled CUPS 2.0.2 with the
freshest gnutls 3.3.13 and the problem is still there. 

Also, setting Encryption to Never both on client and server doesn't resolve
the issue. If I generate the same load or even less load (just 200 parallel
requests), CUPS would periodically get stuck returning the list of
printers, and lpstat will report either one of these:

lpstat: Bad file descriptor
lpstat: Connection reset by peer

strace shows that cupsd is stuck waiting for sendto:

open("/etc/group", O_RDONLY|O_CLOEXEC)  = 15
fstat(15, {st_mode=S_IFREG|0644, st_size=861, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f73284d1000
read(15, "root:x:0:root\nda"..., 4096)  = 861
close(15)                               = 0
munmap(0x7f73284d1000, 4096)            = 0
gettimeofday({1426196041, 665795}, NULL) = 0
write(6, "D [12/Mar/2015:1"..., 69)     = 69
open("/etc/group", O_RDONLY|O_CLOEXEC)  = 15
fstat(15, {st_mode=S_IFREG|0644, st_size=861, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f73284d1000
read(15, "root:x:0:root\nda"..., 4096)  = 861
close(15)                               = 0
munmap(0x7f73284d1000, 4096)            = 0
gettimeofday({1426196041, 666360}, NULL) = 0
write(6, "D [12/Mar/2015:1"..., 225)    = 225
sendto(46, "\2\0\0\0\0\0\0\2\1G\0\22attr"..., 2034, 0, NULL, 0) = 2034
sendto(46, "\4\"\0\31printer-is-a"..., 2037, 0, NULL, 0) = 2037
sendto(46, "A\0\25printer-state"..., 2024, 0, NULL, 0) = 2024
sendto(46, "\4\"\0\31printer-is-a"..., 2047, 0, NULL, 0) = 2047
sendto(46, "B\0\fprinter-name\0"..., 2041, 0, NULL, 0) = 2041
sendto(46, "A\0\25printer-state"..., 2019, 0, NULL, 0) = 2019
sendto(46, "\4\"\0\31printer-is-a"..., 1991, 0, NULL, 0) = 1991
sendto(46, "A\0\25printer-state"..., 2045, 0, NULL, 0) = 2045
sendto(46, "!\0\31printer-state"..., 2026, 0, NULL, 0) = 2026
sendto(46, "!\0\31printer-state"..., 2024, 0, NULL, 0) = 2024
sendto(46, "A\0\25printer-state"..., 2044, 0, NULL, 0) = 2044
sendto(46, "B\0\fprinter-name\0"..., 2019, 0, NULL, 0) = 2019
sendto(46, "!\0\31printer-state"..., 2022, 0, NULL, 0) = 2022
sendto(46, "\4\"\0\31printer-is-a"..., 2029, 0, NULL, 0) = 2029
sendto(46, "A\0\25printer-state"..., 2020, 0, NULL, 0) = 2020
sendto(46, "!\0\31printer-state"..., 2027, 0, NULL, 0) = 2027
sendto(46, "!\0\31printer-state"..., 2015, 0, NULL, 0) = 2015
sendto(46, "!\0\31printer-state"..., 2027, 0, NULL, 0) = 2027
sendto(46, "\4\"\0\31printer-is-a"..., 2026, 0, NULL, 0) = 2026
sendto(46, "B\0\fprinter-name\0"..., 2033, 0, NULL, 0) = 2033
sendto(46, "\4\"\0\31printer-is-a"..., 2019, 0, NULL, 0) = 2019
sendto(46, "\4\"\0\31printer-is-a"..., 2040, 0, NULL, 0) = 2040
sendto(46, "!\0\31printer-state"..., 2039, 0, NULL, 0) = 2039
sendto(46, "A\0\25printer-state"..., 2038, 0, NULL, 0) = 2038
sendto(46, "A\0\25printer-state"..., 2043, 0, NULL, 0) = 2043
sendto(46, "A\0\25printer-state"..., 2028, 0, NULL, 0) = 2028
sendto(46, "A\0\25printer-state"..., 2027, 0, NULL, 0) = 2027
sendto(46, "B\0\fprinter-name\0"..., 2032, 0, NULL, 0) = 2032
sendto(46, "B\0\fprinter-name\0"..., 2040, 0, NULL, 0) = 2040
sendto(46, "A\0\25printer-state"..., 2032, 0, NULL, 0) = 2032
sendto(46, "\4\"\0\31printer-is-a"..., 2041, 0, NULL, 0


Every time the same sendto command:

open("/etc/group", O_RDONLY|O_CLOEXEC)  = 52
fstat(52, {st_mode=S_IFREG|0644, st_size=861, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f73284d1000
read(52, "root:x:0:root\nda"..., 4096)  = 861
close(52)                               = 0
munmap(0x7f73284d1000, 4096)            = 0
gettimeofday({1426196129, 909179}, NULL) = 0
write(6, "D [12/Mar/2015:1"..., 69)     = 69
open("/etc/group", O_RDONLY|O_CLOEXEC)  = 52
fstat(52, {st_mode=S_IFREG|0644, st_size=861, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f73284d1000
read(52, "root:x:0:root\nda"..., 4096)  = 861
close(52)                               = 0
munmap(0x7f73284d1000, 4096)            = 0
gettimeofday({1426196129, 910068}, NULL) = 0
write(6, "D [12/Mar/2015:1"..., 226)    = 226
sendto(42, "\2\0\0\0\0\0\0\1\1G\0\22attr"..., 1994, 0, NULL, 0) = 1994
sendto(42, "B\0\fmarker-names\0"..., 2040, 0, NULL, 0) = 2040
sendto(42, "J\0\0\0\22media-right"..., 2028, 0, NULL, 0) = 2028
sendto(42, "E\0\ndevice-uri\0,s"..., 1982, 0, NULL, 0) = 1982
sendto(42, "A\0\26printer-make-"..., 2024, 0, NULL, 0) = 2024
sendto(42, "!\0\31printer-state"..., 2033, 0, NULL, 0) = 2033
sendto(42, "!\0\16copies-defaul"..., 2017, 0, NULL, 0) = 2017
sendto(42, "D\0\30print-color-m"..., 1985, 0, NULL, 0) = 1985
sendto(42, "B\0\rmarker-colors"..., 2048, 0, NULL, 0) = 2048
sendto(42, "J\0\0\0\vx-dimension"..., 1985, 0, NULL, 0) = 1985
sendto(42, "E\0\25printer-uri-s"..., 2016, 0, NULL, 0) = 2016
sendto(42, "!\0\30job-cancel-af"..., 1997, 0, NULL, 0) = 1997
sendto(42, "D\0\20printer-comma"..., 2031, 0, NULL, 0) = 2031
sendto(42, "B\0\fmarker-names\0"..., 2018, 0, NULL, 0) = 2018
sendto(42, "J\0\0\0\21media-left-"..., 2022, 0, NULL, 0) = 2022
sendto(42, "B\0\fprinter-name\0"..., 2038, 0, NULL, 0) = 2038
sendto(42, "J\0\0\0\22media-right"..., 2038, 0, NULL, 0) = 2038
sendto(42, "E\0\ndevice-uri\0+s"..., 2022, 0, NULL, 0) = 2022
sendto(42, "A\0\26printer-make-"..., 2023, 0, NULL, 0) = 2023
sendto(42, "!\0\31printer-state"..., 2004, 0, NULL, 0) = 2004
sendto(42, "D\0\fmarker-types\0"..., 2028, 0, NULL, 0) = 2028
sendto(42, "J\0\0\0\22media-right"..., 2022, 0, NULL, 0) = 2022
sendto(42, "B\0\fprinter-name\0"..., 2022, 0, NULL, 0) = 2022
sendto(42, "!\0\24job-priority-"..., 2023, 0, NULL, 0) = 2023
sendto(42, "\4!\0\22marker-chang"..., 2039, 0, NULL, 0) = 2039
sendto(42, "!\0\16copies-defaul"..., 2041, 0, NULL, 0) = 2041
sendto(42, "D\0\rsides-default"..., 2026, 0, NULL, 0) = 2026
sendto(42, "!\0\30job-cancel-af"..., 1993, 0, NULL, 0) = 1993
sendto(42, "D\0\20printer-comma"..., 2016, 0, NULL, 0) = 2016
sendto(42, "B\0\fmarker-names\0"..., 2017, 0, NULL, 0) = 2017
sendto(42, "J\0\0\0\23media-botto"..., 2004, 0, NULL, 0) = 2004
sendto(42, "E\0\25printer-uri-s"..., 2046, 0, NULL, 0

Another one:

open("/etc/group", O_RDONLY|O_CLOEXEC)  = 33
fstat(33, {st_mode=S_IFREG|0644, st_size=861, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7f73284d1000
read(33, "root:x:0:root\nda"..., 4096)  = 861
close(33)                               = 0
munmap(0x7f73284d1000, 4096)            = 0
gettimeofday({1426196197, 527150}, NULL) = 0
write(6, "D [12/Mar/2015:1"..., 225)    = 225
sendto(29, "\2\0\0\0\0\0\0\2\1G\0\22attr"..., 2034, 0, NULL, 0) = 2034
sendto(29, "\4\"\0\31printer-is-a"..., 2037, 0, NULL, 0) = 2037
sendto(29, "A\0\25printer-state"..., 2024, 0, NULL, 0) = 2024
sendto(29, "\4\"\0\31printer-is-a"..., 2047, 0, NULL, 0) = 2047
sendto(29, "B\0\fprinter-name\0"..., 2041, 0, NULL, 0) = 2041
sendto(29, "A\0\25printer-state"..., 2019, 0, NULL, 0) = 2019
sendto(29, "\4\"\0\31printer-is-a"..., 1991, 0, NULL, 0) = 1991
sendto(29, "A\0\25printer-state"..., 2045, 0, NULL, 0) = 2045
sendto(29, "!\0\31printer-state"..., 2026, 0, NULL, 0) = 2026
sendto(29, "!\0\31printer-state"..., 2024, 0, NULL, 0) = 2024
sendto(29, "A\0\25printer-state"..., 2044, 0, NULL, 0) = 2044
sendto(29, "B\0\fprinter-name\0"..., 2019, 0, NULL, 0) = 2019
sendto(29, "!\0\31printer-state"..., 2022, 0, NULL, 0) = 2022
sendto(29, "\4\"\0\31printer-is-a"..., 2029, 0, NULL, 0) = 2029
sendto(29, "A\0\25printer-state"..., 2020, 0, NULL, 0) = 2020
sendto(29, "!\0\31printer-state"..., 2027, 0, NULL, 0) = 2027
sendto(29, "!\0\31printer-state"..., 2015, 0, NULL, 0) = 2015
sendto(29, "!\0\31printer-state"..., 2027, 0, NULL, 0) = 2027
sendto(29, "\4\"\0\31printer-is-a"..., 2026, 0, NULL, 0) = 2026
sendto(29, "B\0\fprinter-name\0"..., 2033, 0, NULL, 0) = 2033
sendto(29, "\4\"\0\31printer-is-a"..., 2019, 0, NULL, 0) = 2019
sendto(29, "\4\"\0\31printer-is-a"..., 2040, 0, NULL, 0) = 2040
sendto(29, "!\0\31printer-state"..., 2039, 0, NULL, 0) = 2039
sendto(29, "A\0\25printer-state"..., 2038, 0, NULL, 0) = 2038
sendto(29, "A\0\25printer-state"..., 2043, 0, NULL, 0) = 2043
sendto(29, "A\0\25printer-state"..., 2028, 0, NULL, 0

Another:

open("/etc/group", O_RDONLY|O_CLOEXEC)  = 29
fstat(29, {st_mode=S_IFREG|0644, st_size=861, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7fb4d0c73000
read(29, "root:x:0:root\nda"..., 4096)  = 861
close(29)                               = 0
munmap(0x7fb4d0c73000, 4096)            = 0
gettimeofday({1426196623, 716721}, NULL) = 0
write(6, "D [12/Mar/2015:1"..., 225)    = 225
sendto(26, "\2\0\0\0\0\0\0\1\1G\0\22attr"..., 1994, 0, NULL, 0) = 1994
sendto(26, "B\0\fmarker-names\0"..., 2040, 0, NULL, 0) = 2040
sendto(26, "J\0\0\0\22media-right"..., 2028, 0, NULL, 0) = 2028
sendto(26, "E\0\ndevice-uri\0,s"..., 1982, 0, NULL, 0) = 1982
sendto(26, "A\0\26printer-make-"..., 2024, 0, NULL, 0) = 2024
sendto(26, "!\0\31printer-state"..., 2033, 0, NULL, 0) = 2033
sendto(26, "!\0\16copies-defaul"..., 2017, 0, NULL, 0) = 2017
sendto(26, "D\0\30print-color-m"..., 1985, 0, NULL, 0) = 1985
sendto(26, "B\0\rmarker-colors"..., 2048, 0, NULL, 0) = 2048
sendto(26, "J\0\0\0\vx-dimension"..., 1985, 0, NULL, 0) = 1985
sendto(26, "E\0\25printer-uri-s"..., 2016, 0, NULL, 0) = 2016
sendto(26, "!\0\30job-cancel-af"..., 1997, 0, NULL, 0) = 1997
sendto(26, "D\0\20printer-comma"..., 2031, 0, NULL, 0) = 2031
sendto(26, "B\0\fmarker-names\0"..., 2018, 0, NULL, 0) = 2018
sendto(26, "J\0\0\0\21media-left-"..., 2022, 0, NULL, 0) = 2022
sendto(26, "B\0\fprinter-name\0"..., 2038, 0, NULL, 0) = 2038
sendto(26, "J\0\0\0\22media-right"..., 2038, 0, NULL, 0) = 2038
sendto(26, "E\0\ndevice-uri\0+s"..., 2022, 0, NULL, 0) = 2022
sendto(26, "A\0\26printer-make-"..., 2023, 0, NULL, 0) = 2023
sendto(26, "!\0\31printer-state"..., 2004, 0, NULL, 0) = 2004
sendto(26, "D\0\fmarker-types\0"..., 2028, 0, NULL, 0) = 2028
sendto(26, "J\0\0\0\22media-right"..., 2022, 0, NULL, 0) = 2022
sendto(26, "B\0\fprinter-name\0"..., 2022, 0, NULL, 0) = 2022
sendto(26, "!\0\24job-priority-"..., 2023, 0, NULL, 0) = 2023
sendto(26, "\4!\0\22marker-chang"..., 2039, 0, NULL, 0) = 2039
sendto(26, "!\0\16copies-defaul"..., 2041, 0, NULL, 0) = 2041
sendto(26, "D\0\rsides-default"..., 2026, 0, NULL, 0) = 2026
sendto(26, "!\0\30job-cancel-af"..., 1993, 0, NULL, 0) = 1993
sendto(26, "D\0\20printer-comma"..., 2016, 0, NULL, 0) = 2016
sendto(26, "B\0\fmarker-names\0"..., 2017, 0, NULL, 0) = 2017
sendto(26, "J\0\0\0\23media-botto"..., 2004, 0, NULL, 0) = 2004
sendto(26, "E\0\25printer-uri-s"..., 2046, 0, NULL, 0

Link: https://www.cups.org/str.php?L4586
Version: 1.7-current
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.14 (GNU/Linux)
Comment: GPGTools - https://gpgtools.org

iQIcBAEBCgAGBQJVAgjrAAoJENujp6sI12IjZbUP/0b5sfaMVd+H9wpS+/6eLokb
apwn7973vvgXQrNhj7Th6UtdOnQFHjyVf+S7M/GC0DIfThmwdw+OHbmnOE07NH43
YWefY9JGRmWo87gnFX7HGZDfw51BFTDOhKCuJodEMwZ7gNCXYJIT1iSutdJQ11eK
XJAwxJHwoFfDwcN25WTxikT08k5axgURtk8nmPi5L4Ew8C7Gg8Lr/52Cetd84hJD
91He2A+MbxUmF6DLY190W1N6hQ9GDssZ9rCfIHSITd00FPPvnaM/e98K1R73sTne
QpFQ3lyP8UA3cuqGvd9UNN/aEWjVUXjEBK5Xl2NvggEW0eG61yxvIbPeGTn00EO5
OmBH3JYFCadpvOf1PiFgc8MfQnpGhXau0M86LB/GPjCYawZKTMuN+fTDac5WWmMQ
pmEHh51KuC8X13zaaqK7PXoaVfsHYD8MiqnBUd7Zr7lyAzxS2Vn3WzeMR7hPxTUg
H1lVaAN4OyqnCIhEI+Ib5/vZbn8VxHgcYHRmsJM65XSWp5qoofHFwqJmOm2DxRPO
Em3C8isVsx5Bm3wzZPooP8+ZmnaYxQFMNH4iPlhJpUjs2KRvaVa2FQfObePoa+dH
Go2j+iyUO4WxuJyQltSVnyXXhSC37fMlYczfJlht36RLNlj5VgSuzadFvnv365yy
g1XoWDK5niRU+iRdvsNE
=bpNo
-----END PGP SIGNATURE-----




More information about the cups-devel mailing list