IPP crashes after every successfully completed job since 2.4.2

[Nils-TUD]

Since I upgraded to CUPS 2.4.2, the IPP backend crashes every time after the print is complete. Therefore, I need to manually cancel the job and resume the printer afterwards. I just downgraded to 2.4.1 again and there it still works.

That's the output from coredumpctl gdb:

           PID: 97441 (ipp)
           UID: 0 (root)
           GID: 209 (cups)
        Signal: 11 (SEGV)
     Timestamp: Mon 2022-06-06 07:52:30 CEST (5min ago)
  Command Line: ipp://EPSON482791.local:631/ipp/print 1689 hrniels $'71dYmWUxnrL._AC_SY355_.jpg (870×355)' 1 $'printer-state-reasons=cups-ipp-conformance-failure-report,cups-ipp-missing-job-history printer-is-accepting-jobs PageSize=A4 marker-types=ink,ink,ink,ink noprinter-is-shared marker-low-levels=15,15,15,15 marker-colors=#000000,#00FFFF,#FF00FF,#FFFF00 Ink=COLOR printer-location= marker-levels=68,81,81,81 Duplex=None Collate marker-change-time=1654411089 marker-names=Black\\\\\\ ink,Cyan\\\\\\ ink,Magenta\\\\\\ ink,Yellow\\\\\\ ink printer-state=3 device-uri=dnssd://EPSON%20ET-2750%20Series._ipp._tcp.local/?uuid=cfe92100-67c4-11d4-a45f-e0bb9e482791 printer-uri-supported=ipp://localhost/printers/EPSON_ET-2750_Series print-color-mode=color printer-type=2101276 printer-commands=none printer-state-change-time=1654411111 noprinter-is-temporary number-up=1 finishings=3 marker-high-levels=100,100,100,100 job-uuid=urn:uuid:19b1785f-caee-37f4-77ce-5f292ae8174f job-originating-host-name=localhost date-time-at-creation= date-time-at-processing= time-at-creation=1654494684 time-at-processing=1654494684'
    Executable: /usr/lib/cups/backend/ipp
 Control Group: /system.slice/cups.service
          Unit: cups.service
         Slice: system.slice
       Boot ID: 1d9fce640ed146239ea60ceb88da24df
    Machine ID: 6531e9b368734d409b8b553b97dc4b2d
      Hostname: hrniels-home
       Storage: /var/lib/systemd/coredump/core.ipp.0.1d9fce640ed146239ea60ceb88da24df.97441.1654494750000000.zst (present)
     Disk Size: 334.3K
       Message: Process 97441 (ipp) of user 0 dumped core.

                Module linux-vdso.so.1 with build-id 4bbdd9447359021631434950a65998efe247ea02
                Module libresolv.so.2 with build-id 89a368a6ad1b392d126a2a5beb9c2f61ade00279
                Module libnss_mdns_minimal.so.2 with build-id 8eb55de0d3252a36920a5d74c2da924a902cfff4
                Module libnss_resolve.so.2 with build-id 1790ccea3fad28777fc366683fe31ed6581c9446
                Module libnss_mymachines.so.2 with build-id 51b4a7127dac7bcef5aa6e3046e0509069dcba00
                Module libgpg-error.so.0 with build-id f9aaa96d5ddf6f6872051ed7abcdfe6bdaff9b1c
                Module libgcc_s.so.1 with build-id 0e3de903950e35ae59a5de8c00b1817a4a71ca01
                Module liblz4.so.1 with build-id e63600ab23b2f6997f42fac2fa56e1f02ce159a1
                Module libzstd.so.1 with build-id 3bccb8fe08e48d5ea135b1d0f99de0d771dd752f
                Module liblzma.so.5 with build-id 28b40c7af8098a66af6ee093b6986b91cad7694d
                Module libgcrypt.so.20 with build-id 8bf3cb884124273640de797a3e77d86c98434ea4
                Module libcap.so.2 with build-id 21b00ab76bb16fde56fd741f07233c78069f0579
                Module libsystemd.so.0 with build-id a220b34e873e29bb116d88be0bf11fac7089ef4d
                Module libdl.so.2 with build-id 94198b268228074fa9f405bbedbbae94112593ed
                Module libdbus-1.so.3 with build-id 7f4b16b4b407cbae2d7118d6f99610e29a18a56a
                Module libpthread.so.0 with build-id 95ae4f30a6f12ccbff645d30f8e1a3ee23ec7d36
                Module ld-linux-x86-64.so.2 with build-id fc93487393eea02b5bc6e76e48976fc325294c24
                Module libm.so.6 with build-id 210ec9905e41825671210f8f7d0b24d6c371196a
                Module libz.so.1 with build-id fefe3219a96d682ec98fcfb78866b8594298b5a2
                Module libcrypto.so.1.1 with build-id d54a7ee1e288aeae436d073277ff986e03994b15
                Module libssl.so.1.1 with build-id 25a55106cb13dec5d495c34ca1caf2c2f3114f11
                Module libavahi-client.so.3 with build-id 1858551543958190c653b565cf0eb64609ad908a
                Module libavahi-common.so.3 with build-id 80fda945459a3476ccd1050783dfd5f5c17c479a
                Module libc.so.6 with build-id 388993b6ef62f964bc7bf473c069fbfe957b9e44
                Module libcups.so.2 with build-id 13528a932d9dc7086b873307c702513bed51ec79
                Module ipp with build-id fb58924e9ec8d89716c82b45f50d06b238301e73
                Stack trace of thread 97441:
                #0  0x00007f3fef9fec60 n/a (libc.so.6 + 0x1fec60)
                ELF object binary architecture: AMD x86-64

GNU gdb (GDB) 12.1
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/lib/cups/backend/ipp...
(No debugging symbols found in /usr/lib/cups/backend/ipp)
[New LWP 97441]
[New LWP 97588]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Core was generated by `ipp://EPSON482791.local:631/ipp/print 1689 hrniels 71dYmWUxnrL._AC_SY355_.jpg ('.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f3fef9fec60 in ?? () from /usr/lib/libc.so.6
[Current thread is 1 (Thread 0x7f3feefcf7c0 (LWP 97441))]
(gdb) bt
#0  0x00007f3fef9fec60 in ?? () from /usr/lib/libc.so.6
#1  0x00007f3fefa9dd2a in _httpTLSStop () from /usr/lib/libcups.so.2
#2  0x00007f3fefa8cdf9 in httpReconnect2 () from /usr/lib/libcups.so.2
#3  0x00007f3fefaa66d0 in cupsSendRequest () from /usr/lib/libcups.so.2
#4  0x00007f3fefaa695c in cupsDoIORequest () from /usr/lib/libcups.so.2
#5  0x000055e93eb28c2d in ?? ()
#6  0x00007f3fef829290 in ?? () from /usr/lib/libc.so.6
#7  0x00007f3fef82934a in __libc_start_main () from /usr/lib/libc.so.6
#8  0x000055e93eb2a865 in ?? ()

uname -a:

Linux hrniels-home 5.18.1-arch1-1 #1 SMP PREEMPT_DYNAMIC Mon, 30 May 2022 17:53:11 +0000 x86_64 GNU/Linux

[zdohnal]

Hi @Nils-TUD ,

what crypto library do you use with CUPS? The implementation of _httpTLSStop depends on used crypto library.

Additionally it would be great if you installed debuginfo packages for glibc and cups related packages (names depends on your distro) and provided the backtrace with debuginfo installed.

In case you need to print urgently, switching to plain ipp should work.

Thank you in advance!

[Nils-TUD]

Hi @zdohnal,

I've now rebuilt CUPS with debug infos and obtained symbols for the glibc via debuginfod. Now the backtrace is a bit more helpful:

(gdb) bt full
#0  0x00007f43b61fdc60 in main_arena () from /usr/lib/libc.so.6
No symbol table info available.
#1  0x00007f43b62aa15a in _httpTLSStop (http=0x563bac628800) at /usr/src/debug/cups-2.4.2/cups/tls-openssl.c:1152
        context = 0x563bac6c5200
#2  0x00007f43b628ee59 in httpReconnect2 (http=http@entry=0x563bac628800, msec=msec@entry=30000, cancel=cancel@entry=0x0) at http.c:2357
        addr = <optimized out>
#3  0x00007f43b62a6718 in cupsSendRequest (http=http@entry=0x563bac628800, request=request@entry=0x563bac705b60, 
    resource=resource@entry=0x7ffca4a16f50 "/ipp/print", length=length@entry=346) at request.c:635
        status = 32764
        got_status = <optimized out>
        state = <optimized out>
        expect = <optimized out>
        date = "\377\377\377\377\377\377\377\377\240\327b\254;V\000\000\027\000\000\000\000\000\000\000V\243'\266C\177\000\000\377\377\377\377\377\377\377\377\304䠤\374\177\000\000`[p\254;V\000\000Ǣ'\266C\177", '\000' <repeats 11 times>, "\265x1i\245Gr\377\377\377\377\000\000\000\000\200\377\377\377\377\377\377\377\000\000\000\000\000\000\000\000\000\265x1i\245Gr\360_o\254;V\000\000\200\377\377\377\377\377\377\377\000\000\000\000\000\000\000\000\000\265x1i\245Gr\360_o\254;V\000\000\200\377\377\377\377\377\377\377\000\000\000\000\000\000\000\000\377\377\377\377\000\000\000\000\360_o\254;V\000\000Po\241\244\374\177\000\000`[p\254;V\000\000\363\310\t"...
        digest = <optimized out>
#4  0x00007f43b62a6acc in cupsDoIORequest (http=http@entry=0x563bac628800, request=request@entry=0x563bac705b60, 
    resource=resource@entry=0x7ffca4a16f50 "/ipp/print", infile=infile@entry=-1, outfile=outfile@entry=-1) at request.c:203
        response = <optimized out>
        length = 346
        status = <optimized out>
        fileinfo = {st_dev = 94814295197696, st_ino = 139928795656856, st_nlink = 94814295197696, st_mode = 3056122961, st_uid = 32579, 
          st_gid = 2762040900, __pad0 = 32764, st_rdev = 94814295197696, st_size = 140723070494224, st_blksize = 139928795665793, st_blocks = 4294967296, 
          st_atim = {tv_sec = 858993459201, tv_nsec = 3275364211029339904}, st_mtim = {tv_sec = 2305957858374477132, tv_nsec = 8028075770728756274}, 
          st_ctim = {tv_sec = 482922278766, tv_nsec = 0}, __glibc_reserved = {0, 0, 0}}
        bytes = <optimized out>
        buffer = '\000' <repeats 9544 times>...
#5  0x00007f43b62a6e65 in cupsDoRequest (http=http@entry=0x563bac628800, request=request@entry=0x563bac705b60, 
    resource=resource@entry=0x7ffca4a16f50 "/ipp/print") at request.c:293
No locals.
#6  0x0000563babe2b70a in main (argc=6, argv=0x7ffca4a1bca8) at ipp.c:2067
        i = <optimized out>
        send_options = <optimized out>
        num_options = 0
        options = 0x0
        device_uri = <optimized out>
        scheme = "ipp", '\000' <repeats 251 times>
        hostname = "EPSON482791.local", '\000' <repeats 1006 times>
        resource = "/ipp/print", '\000' <repeats 1013 times>
        addrname = "[v1.fe80::e2bb:9eff:fe48:2791+enp0s31f6]", '\000' <repeats 215 times>
        optptr = <optimized out>
        name = <optimized out>
        value = <optimized out>
        sep = <optimized out>
        password_tries = 0
        addrlist = <optimized out>
        snmp_enabled = <optimized out>
        snmp_fd = <optimized out>
        start_count = 406
        page_count = 0
        have_supplies = 1
        num_files = 0
        files = 0x0
        compatfile = 0x0
        compatsize = 0
        port = 631
        uri = "ipp://EPSON482791.local:631/ipp/print", '\000' <repeats 986 times>
--Type <RET> for more, q to quit, c to continue without paging--
        print_job_name = '\000' <repeats 1023 times>
        http_status = <optimized out>
        ipp_status = <optimized out>
        http = <optimized out>
        request = 0x563bac705b60
        response = <optimized out>
        supported = 0x563bac6f7d50
        start_time = <optimized out>
        contimeout = <optimized out>
        delay = 1
        prev_delay = 0
        compression = 0x0
        waitjob = <optimized out>
        waitjob_tries = 0
        waitprinter = <optimized out>
        monitor = {uri = 0x7ffca4a17350 "ipp://EPSON482791.local:631/ipp/print", hostname = 0x7ffca4a16b50 "EPSON482791.local", 
          user = 0x7ffca4a1c870 "hrniels", resource = 0x7ffca4a16f50 "/ipp/print", port = 631, version = 20, job_id = 1, job_reasons = 0, create_job = 1, 
          get_job_attrs = 1, job_name = 0x7ffca4a1c878 "Home - CUPS 2.4.2", encryption = HTTP_ENCRYPTION_IF_REQUESTED, job_state = IPP_JSTATE_PROCESSING, 
          printer_state = IPP_PSTATE_PROCESSING, retryable = 1}
        job_id_attr = <optimized out>
        job_id = <optimized out>
        job_sheets = <optimized out>
        job_state = <optimized out>
        compression_sup = <optimized out>
        copies_sup = 0x563bac6f6270
        cups_version = 0x0
        encryption_sup = <optimized out>
        format_sup = <optimized out>
        job_auth = <optimized out>
        media_col_sup = 0x563bac6f7da0
        operations_sup = <optimized out>
        doc_handling_sup = 0x0
        printer_state = <optimized out>
        printer_accepting = <optimized out>
        print_color_mode_sup = 0x563bac6f7470
        create_job = 1
        get_job_attrs = 1
        send_document = <optimized out>
        validate_job = <optimized out>
        validate_retried = <optimized out>
        copies = <optimized out>
        copies_remaining = 0
        content_type = <optimized out>
        final_content_type = <optimized out>
        document_format = <optimized out>
        fd = <optimized out>
        bytes = 0
        buffer = "\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\320\377\377\377\375\376\376\376\001\375\375\375\373\373\373\377\372\372\372\003\370\370\370\365\365\365\361\361\361\355\355\355\377\351\351\351\002\344\344\344\337\337\337\334\334\334\377\326\326\326\000\323\323\323\337\377\377\377\374xxx\200\377\377\377\362\377\377\377\033d\316\000\000\000dsnd\000\000\017\240\001\000ǀ\377\377\377\330\377\377\377\001\320\320\320\325\325\325\377\332\332\332\002\335\335\335\343\343\343\346\346\346\377\353\353\353\003\360\360\360\362\362\362\365\365\365\370\370\370\377\373\373\373\001\374\374\374\375\375\375\377\376\376\376\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377\200\377\377\377"...
        action = {__sigaction_handler = {sa_handler = 0x563babe2f6f0 <sigterm_handler>, sa_sigaction = 0x563babe2f6f0 <sigterm_handler>}, sa_mask = {
            __val = {16384, 0 <repeats 15 times>}}, sa_flags = 0, sa_restorer = 0x0}
        version = 20
        ppd = 0x0
        pc = 0x0
        input = {fds_bits = {0 <repeats 16 times>}}

That also answers your other question: I'm using openssl, apparently :)

[michaelrsweet]

@Nils-TUD It looks like a stale "tls" pointer - the OpenSSL code isn't clearing it like the GNU TLS code.

Try the following fix:

[master c0c403744] Fix OpenSSL crash bug - "tls" pointer wasn't cleared after freeing it (Issue #409)

[Nils-TUD]

Yes, that fixes the problem for me. Thanks!