Some time ago, an update broke printing via CUPS. Unfortunately I don't have any idea which version it was. The output from `coredumpctl gdb`: PID: 30450 (gs) UID: 4 (lp) GID: 7 (lp) Signal: 11 (SEGV) Timestamp: Wed 2017-01-25 18:12:18 CET (36s ago) Command Line: gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sstdout=%stderr -sOutputFile=%stdout -sDEVICE=cups -sMediaClass=Cassette -sMediaType=Plain -r600x600 -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dcupsBitsPerColor=8 -dcupsColorOrder=0 -dcupsColorSpace=6 -dcupsCompression=5 -dcupsRowFeed=2 -scupsPageSizeName=A4 -I/usr/share/cups/fonts -c <</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>setpagedevice -f -_ Executable: /usr/bin/gs Control Group: /system.slice/cups.service Unit: cups.service Slice: system.slice Boot ID: a540585c8bc34dc6a5cd3891ce45547b Machine ID: 4635c494745e39c7f7ec84a55576cbbe Hostname: scarlet.dev-zero.ch Storage: /var/lib/systemd/coredump/core.gs.4.a540585c8bc34dc6a5cd3891ce45547b.30450.1485364338000000000000.lz4 Message: Process 30450 (gs) of user 4 dumped core. GNU gdb (Gentoo 7.12 vanilla) 7.12 Copyright (C) 2016 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://bugs.gentoo.org/>. 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/bin/gs...Reading symbols from /usr/lib64/debug//usr/bin/gs.debug...done. done. [New LWP 30450] [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib64/libthread_db.so.1". Core was generated by `gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -ss'. Program terminated with signal SIGSEGV, Segmentation fault. #0 gdev_mem_set_line_ptrs (mdev=mdev@entry=0x5645833ee238, base=<optimized out>, base@entry=0x7fb3d3ca0372 "", raster=raster@entry=19832, line_ptrs=<optimized out>, setup_height=setup_height@entry=5750) at ./base/gdevmem.c:543 543 *pptr++ = scan_line; (gdb) bt #0 gdev_mem_set_line_ptrs (mdev=mdev@entry=0x5645833ee238, base=<optimized out>, base@entry=0x7fb3d3ca0372 "", raster=raster@entry=19832, line_ptrs=<optimized out>, setup_height=setup_height@entry=5750) at ./base/gdevmem.c:543 #1 0x00007fb3de851834 in gx_default_setup_buf_device (bdev=0x5645833ee238, buffer=0x7fb3d3ca0372 "", raster=19832, line_ptrs=0x7fb3da9608c2, y=<optimized out>, setup_height=5750, full_height=5750) at ./base/gdevprn.c:1556 #2 0x00007fb3de88f69c in clist_rasterize_lines (dev=dev@entry=0x7fb3da9f8078, y=y@entry=0, line_count=<optimized out>, line_count@entry=1, bdev=0x5645833ee238, render_plane=render_plane@entry=0x7fffe17ea360, pmy=pmy@entry=0x7fffe17ea354) at ./base/gxclread.c:733 #3 0x00007fb3de88f990 in clist_get_bits_rectangle (dev=dev@entry=0x7fb3da9f8078, prect=prect@entry=0x7fffe17ea8b0, params=params@entry=0x7fffe17ea8c0, unread=unread@entry=0x0) at ./base/gxclread.c:629 #4 0x00007fb3de8b5612 in clist_get_bits_rect_mt (dev=0x7fb3da9f8078, prect=0x7fffe17ea8b0, params=0x7fffe17ea8c0, unread=0x0) at ./base/gxclthrd.c:776 #5 0x00007fb3deb1a648 in gx_default_get_bits (dev=0x7fb3da9f8078, y=<optimized out>, data=<optimized out>, actual_data=0x7fffe17eab90) at ./base/gdevdgbr.c:54 #6 0x00007fb3de851e58 in gdev_prn_get_bits (pdev=pdev@entry=0x7fb3da9f8078, y=y@entry=0, str=str@entry=0x56458389b8d0 "", actual_data=actual_data@entry=0x7fffe17eab90) at ./base/gdevprn.c:1641 #7 0x00007fb3dea52704 in cups_print_chunked (pdev=pdev@entry=0x7fb3da9f8078, src=src@entry=0x56458389b8d0 "", dst=dst@entry=0x5645838a0680 "", srcbytes=srcbytes@entry=19832) at ./cups/gdevcups.c:4609 #8 0x00007fb3dea53553 in cups_print_pages (pdev=0x7fb3da9f8078, fp=<optimized out>, num_copies=<optimized out>) at ./cups/gdevcups.c:3031 #9 0x00007fb3de853c20 in gdev_prn_output_page_aux (bg_print_ok=0, seekable=0, flush=1, num_copies=1, pdev=0x7fb3da9f8078) at ./base/gdevprn.c:1091 #10 gdev_prn_output_page (pdev=pdev@entry=0x7fb3da9f8078, num_copies=1, flush=1) at ./base/gdevprn.c:1128 #11 0x00007fb3dea553ec in cups_output_page (pdev=0x7fb3da9f8078, num_copies=<optimized out>, flush=<optimized out>) at ./cups/gdevcups.c:2862 #12 0x00007fb3dea78696 in gs_output_page (pgs=0x5645832799c8, num_copies=1, flush=1) at ./base/gsdevice.c:210 #13 0x00007fb3debbb1e5 in zoutputpage (i_ctx_p=0x564583295eb0) at ./psi/zdevice.c:369 #14 0x00007fb3deb7baca in interp (pi_ctx_p=pi_ctx_p@entry=0x564583242650, pref=<optimized out>, perror_object=perror_object@entry=0x7fffe17eb6c0) at ./psi/interp.c:1197 #15 0x00007fb3deb7d4ba in gs_call_interp (perror_object=0x7fffe17eb6c0, pexit_code=0x7fffe17eb6b0, user_errors=1, pref=0x7fffe17eb520, pi_ctx_p=0x564583242650) at ./psi/interp.c:511 #16 gs_interpret (pi_ctx_p=0x564583242650, pref=pref@entry=0x7fffe17eb650, user_errors=1, pexit_code=0x7fffe17eb6b0, perror_object=<optimized out>) at ./psi/interp.c:468 #17 0x00007fb3deb6edf4 in gs_main_interpret (perror_object=<optimized out>, pexit_code=<optimized out>, user_errors=<optimized out>, pref=0x7fffe17eb650, minst=<optimized out>) at ./psi/imain.c:245 #18 gs_main_run_string_end (minst=<optimized out>, user_errors=<optimized out>, pexit_code=<optimized out>, perror_object=<optimized out>) at ./psi/imain.c:663 #19 0x00007fb3deb71227 in run_string (options=2, str=0x7fb3dec28821 ".runstdin", minst=0x5645832425b0) at ./psi/imainarg.c:977 #20 swproc (minst=minst@entry=0x5645832425b0, arg=arg@entry=0x7fffe17eec51 "-_", pal=pal@entry=0x7fffe17ebdf0) at ./psi/imainarg.c:331 #21 0x00007fb3deb72ac6 in gs_main_init_with_args (minst=0x5645832425b0, argc=26, argv=0x7fffe17ec928) at ./psi/imainarg.c:222 #22 0x0000564581efab1a in main (argc=26, argv=0x7fffe17ec928) at ./psi/dxmainc.c:86
Ok, I figured out what changed: the bug only occurs when I set the color model to CMYK (in the Color tab of the print dialog). When setting it to RGB Color, printing works.
I have build the latest ghostscript on my linux box, and: gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sstdout=%stderr -sOutputFile=out.cups -sDEVICE=cups -sMediaClass=Cassette -sMediaType=Plain -r600x600 -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dcupsBitsPerColor=8 -dcupsColorOrder=0 -dcupsColorSpace=6 -dcupsCompression=5 -dcupsRowFeed=2 -scupsPageSizeName=A4 -I/usr/share/cups/fonts -c "<</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>" setpagedevice -f examples/tiger.eps works fine. Same with the released version of gs9.20. If you can provide me an actual command line and input file to run to get to see the problem, I (or one of my colleagues) will look again.
Created attachment 13316 [details] Input triggering the segfault This input can trigger the segfault on my machine BUT I also have to set the environment variables as follows (salvaged using a script which does `env > /tmp/debug_env; tee /tmp/debug_input | /usr/bin/gs.orig "$@"`): CUPS_DOCROOT=/usr/share/cups/html CUPS_CACHEDIR=/var/cache/cups LANG=de_CH.UTF-8 CUPS_ENCRYPTION=IfRequested PRINTER_INFO=Canon MX860 series CUPS_FILETYPE=document CUPS_REQUESTROOT=/var/spool/cups SERVER_ADMIN=root@scarlet.dev-zero.ch CUPS_SERVERBIN=/usr/libexec/cups CUPS_MAX_MESSAGE=2047 USER=root CUPS_DATADIR=/usr/share/cups PWD=/ HOME=/tmp PRINTER_LOCATION=Zuhause RIP_MAX_CACHE=128m CONTENT_TYPE=application/pdf CHARSET=utf-8 IPP_PORT=631 TMPDIR=/tmp CUPS_STATEDIR=/run/cups CUPS_FONTPATH=/usr/share/cups/fonts CUPS_SERVERROOT=/etc/cups PPD=/etc/cups/ppd/CanonMX860.ppd SOFTWARE=CUPS/2.2.2 CUPS_SERVER=/run/cups/cups.sock SHLVL=1 PRINTER=CanonMX860 FINAL_CONTENT_TYPE=application/vnd.cups-raster DEVICE_URI=bjnp://192.168.179.40:8611 PATH=/usr/libexec/cups/filter:/usr/bin:/usr/sbin:/bin:/usr/bin AUTH_INFO_REQUIRED=none PRINTER_STATE_REASONS=marker-supply-low-warning,bjnp.Magenta-ink-low-warning _=/usr/bin/env When I run the command `gs.orig -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sstdout=%stderr -sOutputFile=out.cups -sDEVICE=cups -sMediaClass=Cassette -sMediaType=Plain -r600x600 -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dcupsBitsPerColor=8 -dcupsColorOrder=0 -dcupsColorSpace=6 -dcupsCompression=5 -dcupsRowFeed=2 -scupsPageSizeName=A4 -I/usr/share/cups/fonts -c "<</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>" setpagedevice -f /tmp/debug_input` as a normal user without setting the environment variables, `gs` succeeds.
ok, it is sufficient to set RIP_MAX_CACHE=128m. So, given the attached input I can reproduce the segfault using the following: ~$ RIP_MAX_CACHE=128m gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sstdout=%stderr -sOutputFile=out.cups -sDEVICE=cups -sMediaClass=Cassette -sMediaType=Plain -r600x600 -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dcupsBitsPerColor=8 -dcupsColorOrder=0 -dcupsColorSpace=6 -dcupsCompression=5 -dcupsRowFeed=2 -scupsPageSizeName=A4 -I/usr/share/cups/fonts -c "<</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>" setpagedevice -f /tmp/debug_input INFO: Start rendering... INFO: Processing page 1... Speicherzugriffsfehler (core dumped) and gdb shows the same line as cause for the error: Core was generated by `gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -ss'. Program terminated with signal SIGSEGV, Segmentation fault. #0 gdev_mem_set_line_ptrs (mdev=mdev@entry=0x5633e8f67528, base=<optimized out>, base@entry=0x7f147c35b372 "", raster=raster@entry=19800, line_ptrs=<optimized out>, setup_height=setup_height@entry=5759) at ./base/gdevmem.c:543 543 *pptr++ = scan_line; (gdb) bt #0 gdev_mem_set_line_ptrs (mdev=mdev@entry=0x5633e8f67528, base=<optimized out>, base@entry=0x7f147c35b372 "", raster=raster@entry=19800, line_ptrs=<optimized out>, setup_height=setup_height@entry=5759) at ./base/gdevmem.c:543 #1 0x00007f1486f0c834 in gx_default_setup_buf_device (bdev=0x5633e8f67528, buffer=0x7f147c35b372 "", raster=19800, line_ptrs=0x7f148301a21a, y=<optimized out>, setup_height=5759, full_height=5759) at ./base/gdevprn.c:1556 #2 0x00007f1486f4a69c in clist_rasterize_lines (dev=dev@entry=0x7f14830b3078, y=y@entry=0, line_count=<optimized out>, line_count@entry=1, bdev=0x5633e8f67528, render_plane=render_plane@entry=0x7fff195f9020, pmy=pmy@entry=0x7fff195f9014) at ./base/gxclread.c:733 #3 0x00007f1486f4a990 in clist_get_bits_rectangle (dev=dev@entry=0x7f14830b3078, prect=prect@entry=0x7fff195f9580, params=params@entry=0x7fff195f9590, unread=unread@entry=0x0) at ./base/gxclread.c:629 #4 0x00007f1486f70612 in clist_get_bits_rect_mt (dev=0x7f14830b3078, prect=0x7fff195f9580, params=0x7fff195f9590, unread=0x0) at ./base/gxclthrd.c:776 #5 0x00007f14871d5648 in gx_default_get_bits (dev=0x7f14830b3078, y=<optimized out>, data=<optimized out>, actual_data=0x7fff195f9860) at ./base/gdevdgbr.c:54 #6 0x00007f1486f0ce58 in gdev_prn_get_bits (pdev=pdev@entry=0x7f14830b3078, y=y@entry=0, str=str@entry=0x5633e91b3790 "", actual_data=actual_data@entry=0x7fff195f9860) at ./base/gdevprn.c:1641 #7 0x00007f148710d704 in cups_print_chunked (pdev=pdev@entry=0x7f14830b3078, src=src@entry=0x5633e91b3790 "", dst=dst@entry=0x5633e91b8520 "", srcbytes=srcbytes@entry=19800) at ./cups/gdevcups.c:4609 #8 0x00007f148710e553 in cups_print_pages (pdev=0x7f14830b3078, fp=<optimized out>, num_copies=<optimized out>) at ./cups/gdevcups.c:3031 #9 0x00007f1486f0ec20 in gdev_prn_output_page_aux (bg_print_ok=0, seekable=0, flush=1, num_copies=1, pdev=0x7f14830b3078) at ./base/gdevprn.c:1091 #10 gdev_prn_output_page (pdev=pdev@entry=0x7f14830b3078, num_copies=1, flush=1) at ./base/gdevprn.c:1128 #11 0x00007f14871103ec in cups_output_page (pdev=0x7f14830b3078, num_copies=<optimized out>, flush=<optimized out>) at ./cups/gdevcups.c:2862 #12 0x00007f1487133696 in gs_output_page (pgs=0x5633e8dbc9c8, num_copies=1, flush=1) at ./base/gsdevice.c:210 #13 0x00007f14872761e5 in zoutputpage (i_ctx_p=0x5633e8dd8eb0) at ./psi/zdevice.c:369 #14 0x00007f1487236aca in interp (pi_ctx_p=pi_ctx_p@entry=0x5633e8d85650, pref=<optimized out>, perror_object=perror_object@entry=0x7fff195fa370) at ./psi/interp.c:1197 #15 0x00007f14872384ba in gs_call_interp (perror_object=0x7fff195fa370, pexit_code=0x7fff195fa36c, user_errors=1, pref=0x7fff195fa1f0, pi_ctx_p=0x5633e8d85650) at ./psi/interp.c:511 #16 gs_interpret (pi_ctx_p=0x5633e8d85650, pref=pref@entry=0x7fff195fa320, user_errors=1, pexit_code=0x7fff195fa36c, perror_object=<optimized out>) at ./psi/interp.c:468 #17 0x00007f1487229df4 in gs_main_interpret (perror_object=<optimized out>, pexit_code=<optimized out>, user_errors=<optimized out>, pref=0x7fff195fa320, minst=<optimized out>) at ./psi/imain.c:245 #18 gs_main_run_string_end (minst=<optimized out>, user_errors=<optimized out>, pexit_code=<optimized out>, perror_object=<optimized out>) at ./psi/imain.c:663 #19 0x00007f148722bd4b in run_string (options=<optimized out>, str=0x5633e927b570 "<2f746d702f64656275675f696e707574>.runfile", minst=0x5633e8d855b0) at ./psi/imainarg.c:977 #20 runarg (minst=minst@entry=0x5633e8d855b0, pre=pre@entry=0x7f14872bbfb3 "", arg=arg@entry=0x7fff195fc30b "/tmp/debug_input", post=post@entry=0x7f14872e3877 ".runfile", options=options@entry=3) at ./psi/imainarg.c:967 #21 0x00007f148722dbf8 in argproc (arg=0x7fff195fc30b "/tmp/debug_input", minst=0x5633e8d855b0) at ./psi/imainarg.c:900 ---Type <return> to continue, or q <return> to quit---q
RIP_MAX_CACHE=128m looks suspicious - can you try doubling it?
A4 at r600x600 at 24bit is about 120MB, so if you go over to 32bit (cmyk) it would need 160MB or thereabouts.
yes, looks good: ~ $ RIP_MAX_CACHE=256m gs -dQUIET -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sstdout=%stderr -sOutputFile=out.cups -sDEVICE=cups -sMediaClass=Cassette -sMediaType=Plain -r600x600 -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dcupsBitsPerColor=8 -dcupsColorOrder=0 -dcupsColorSpace=6 -dcupsCompression=5 -dcupsRowFeed=2 -scupsPageSizeName=A4 -I/usr/share/cups/fonts -c "<</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>" setpagedevice -f /tmp/debug_input INFO: Start rendering... INFO: Processing page 1... INFO: Processing page 2... INFO: Rendering completed
In the beginning of CUPS the RIP_MAX_CACHE used by CUPS was 8 MB and some years ago I raised this to 128 MB, AFAIR due to too slow processing. It seems that in general the buffer does not need to hold the whole page. AFAIR Ghostscript goes into a banding mode when it has not enough memory for a whole page. So raising the buffer size makes Ghostscript more often not using the banding mode. Perhaps the problem is some bug only acting in the banding mode.
(In reply to Till Kamppeter from comment #8) > In the beginning of CUPS the RIP_MAX_CACHE used by CUPS was 8 MB and some > years ago I raised this to 128 MB, AFAIR due to too slow processing. > > It seems that in general the buffer does not need to hold the whole page. > AFAIR Ghostscript goes into a banding mode when it has not enough memory for > a whole page. So raising the buffer size makes Ghostscript more often not > using the banding mode. > > Perhaps the problem is some bug only acting in the banding mode. Yes. Hintaks suggestion is a workaround, not a fix.
Robin, this is also how I understand it. Raising the buffer is a workaround. It seems to make Ghostscript staying in full-page mode and not going into the banding mode where the bug is. By the backtrace you can perhaps recognize whether Ghostscript has actually switched into banding mode.
It /should/ be possible to trigger this by using the Ghostscript option -K### to limit the memory similarly to the RIP_MAX_CACHE. Also, this issue was raised previously in bug 691170 that claims gs_exit calls should call exit(1) I tried: bin/gs -K128m -Z: @xx -_ < Bug697504.pdf where xx contains the args from the report: -dPARANOIDSAFER -dNOPAUSE -dBATCH -dNOINTERPOLATE -dNOMEDIAATTRS -sstdout=%stderr -sOutputFile=/dev/null -sDEVICE=cups -sMediaClass=Cassette -sMediaType=Plain -r600x600 -dDEVICEWIDTHPOINTS=595 -dDEVICEHEIGHTPOINTS=842 -dcupsBitsPerColor=8 -dcupsColorOrder=0 -dcupsColorSpace=6 -dcupsCompression=5 -dcupsRowFeed=2 -scupsPageSizeName=A4 -I/usr/share/cups/fonts -c <</.HWMargins[0.000000 0.000000 0.000000 0.000000] /Margins[0 0]>>setpagedevice and it fails with a Segmentation Fault as well. We should probably add a test to make sure gs doesn't segfault on any reasonable -K settings (do a sequence of ever decreasing values) so that we spot all the places that may not be checking for an allocation failure. ISTR we used to do something like this, but haven't been testing that for a while.
Minor issue, the -K# doesn't take the modifier 'm', but I did a loop with decreasing values of -K from 15000 (15 Mb) down and it renders fine down to 13100, then it starts failing with Unrecoverable VMerror (but no segfault) down to 4800 where it starts segfaulting. At 3200 it stops segfaulting, all the way down to 100 except for 500. So we need to look at those -K values and fix those.
A quick look seems to show that the PS initialization isn't complete (init2) but it is still trying to use the PS interpreter error handling and is not exiting. That particular problem is now fixed in commit c279474, but I don't know if it fixes the problem with RIP_MAX_CACHE=128m since the limits I was using with -K are *MUCH* smaller (15000 is roughly 15 Mb) Segfault in low memory configurations Testing with -K values for bug 697504, I was able to reproduce some segfaults, but don't know if they relate to the one mentioned here and on bug 691170 (which was closed as fixed), but these need to get fixed in any case. These occured because the init2 had not completed, but the interp was being called to do more stuff than it could reasonably hope to do in this case. Testing with -K values from 15000 down to 100 by 100 now no longer segfaults. Please retest in your configuration with this patch.
We assume this has been fixed.