From owner-freebsd-ports@freebsd.org Wed Jun 17 14:04:46 2020 Return-Path: Delivered-To: freebsd-ports@mailman.nyi.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.nyi.freebsd.org (Postfix) with ESMTP id 341F934FC53 for ; Wed, 17 Jun 2020 14:04:46 +0000 (UTC) (envelope-from peo@nethead.se) Received: from ns1.nethead.se (ns1.nethead.se [5.150.237.139]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "ns1.nethead.se", Issuer "Let's Encrypt Authority X3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 49n6JY2ryhz3b8R for ; Wed, 17 Jun 2020 14:04:45 +0000 (UTC) (envelope-from peo@nethead.se) X-Virus-Scanned: amavisd-new at Nethead AB DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=nethead.se; s=NETHEADSE; t=1592402681; bh=KIVME5EqY8jGMLH58ulxfKYgiOhpV5KiBTYOgAFdbrw=; h=Subject:To:Cc:References:From:Date:In-Reply-To; b=ubpkTW8F85arTC9M6bsKh0KmRi9Z39RAOPlRS7lJhJaZFHBZ2papMMyR8laPbcgMr OLE2UUW60nv7VDZE/EHU5+IkigIlnmCYADV55NoSVog43wWE+ntmnn32tBF4pmKFy8 Cs0a8lw8wnzUidxerBIuRLOm/0pbG1bw3N+ogk54= Subject: Re: cups-pdf crash status -139 To: Michael Gmelin Cc: FreeBSD References: <4910A962-B20D-4D0B-A1A2-B57E2B2F4434@grem.de> <20200617112333.5cb48ffa@bsd64.grem.de> From: Per olof Ljungmark Message-ID: Date: Wed, 17 Jun 2020 16:04:38 +0200 User-Agent: Mozilla/5.0 (X11; FreeBSD amd64; rv:68.0) Gecko/20100101 Thunderbird/68.6.0 MIME-Version: 1.0 In-Reply-To: <20200617112333.5cb48ffa@bsd64.grem.de> Content-Type: text/plain; charset=utf-8; format=flowed Content-Language: en-US Content-Transfer-Encoding: 8bit X-Rspamd-Queue-Id: 49n6JY2ryhz3b8R X-Spamd-Bar: --- Authentication-Results: mx1.freebsd.org; dkim=pass header.d=nethead.se header.s=NETHEADSE header.b=ubpkTW8F; dmarc=pass (policy=none) header.from=nethead.se; spf=pass (mx1.freebsd.org: domain of peo@nethead.se designates 5.150.237.139 as permitted sender) smtp.mailfrom=peo@nethead.se X-Spamd-Result: default: False [-3.46 / 15.00]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-0.99)[-0.990]; R_DKIM_ALLOW(-0.20)[nethead.se:s=NETHEADSE]; FROM_HAS_DN(0.00)[]; R_SPF_ALLOW(-0.20)[+ip4:5.150.237.139:c]; NEURAL_HAM_LONG(-0.99)[-0.991]; MIME_GOOD(-0.10)[text/plain]; TO_MATCH_ENVRCPT_SOME(0.00)[]; TO_DN_ALL(0.00)[]; DKIM_TRACE(0.00)[nethead.se:+]; RCPT_COUNT_TWO(0.00)[2]; DMARC_POLICY_ALLOW(-0.50)[nethead.se,none]; NEURAL_HAM_SHORT(-0.48)[-0.477]; RCVD_COUNT_ZERO(0.00)[0]; FROM_EQ_ENVFROM(0.00)[]; MIME_TRACE(0.00)[0:+]; ASN(0.00)[asn:8473, ipnet:5.150.192.0/18, country:SE]; MID_RHS_MATCH_FROM(0.00)[] X-BeenThere: freebsd-ports@freebsd.org X-Mailman-Version: 2.1.33 Precedence: list List-Id: Porting software to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 17 Jun 2020 14:04:46 -0000 On 2020-06-17 11:23, Michael Gmelin wrote: > > > On Wed, 17 Jun 2020 09:43:35 +0200 > Per olof Ljungmark wrote: > >> On 2020-06-16 12:15, Michael Gmelin wrote: >>> >>> >>>> On 16. Jun 2020, at 11:47, Per olof Ljungmark >>>> wrote: >>>> >>>> On 2020-06-15 16:14, Michael Gmelin wrote: >>>>>> On Mon, 15 Jun 2020 12:03:17 +0200 >>>>>> Per olof Ljungmark wrote: >>>>>> On 2020-06-15 09:50, Michael Gmelin wrote: >>>>>>> >>>>>>> >>>>>>>> On 15. Jun 2020, at 09:45, Per olof Ljungmark >>>>>>>> wrote: >>>>>>> >>>>>>> What happens if you run the gs command on the pdf you’re >>>>>>> printing directly: >>>>>>> >>>>>>> >>>>>>>> gs -q -dNOPAUSE -dBATCH -dSAFER -dNOMEDIAATTRS -sstdout=? >>>>>>>> -sDEVICE=ps2write -dShowAcroForm -sOUTPUTFILE=? >>>>>>>> -dLanguageLevel=2 -r300 -dCompressFonts=false -dNoT3CCITT >>>>>>>> -dNOINTERPOLATE ? ? -f ? >>>>>> >>>>>> A PDF is created. >>>>>> >>>>>> And, according to logs gs is OK: >>>>>> >>>>>> D [15/Jun/2020:09:16:23 +0200] [Job 1070] Wrote 1 pages... >>>>>> D [15/Jun/2020:09:16:23 +0200] [Job 1070] PID 37126 (pstops) >>>>>> exited with no errors. >>>>>> D [15/Jun/2020:09:16:23 +0200] [Job 1070] PID 37125 (gs) exited >>>>>> with no errors. >>>>>> D [15/Jun/2020:09:16:23 +0200] [Job 1070] PID 37123 >>>>>> (/usr/local/libexec/cups/filter/pdftops) exited with no errors. >>>>>> I [15/Jun/2020:09:16:23 +0200] [Job 1070] Backend returned status >>>>>> -139 (crashed) >>>>> Are you printer(s) shown as okay in the cups web UI? (like, not >>>>> temporarily halted, stopped, etc.?). I sometimes had some issues >>>>> after upgrading, especially with hplip. >>>>> This upstream issue reported earlier this year sounds similar to >>>>> what you're seeing, maybe it helps: >>>>> https://github.com/apple/cups/issues/5765 >>>> >>>> The cups-pdf printer is paused with "Backend failed" but all other >>>> printers are OK. HPLIP is not installed. >>> >>> Can you enable the cups-pdf printer using the “cupsenable” command? >>> And if so, will it stay enabled or go back to paused/failed at the >>> next attempt? >> >> It reverts to "Backend failed". >> >> Just tried to add the cups-pdf printer to the 12-STABLE workstation >> I'm writing this on with identical result so by now I see this on >> three different boxes, all running 12-STABLE. Also, I am confident >> that the problem surfaced after the updates to cups in late March. >> >> If I have the time at some point I could try to revert to an older >> version but it would be nicer to sort the problem. >> >> Not sure how to proceed from here... >> > > Could you share your relevant config files, so I can try to reproduce > the problem? > Some more info maybe relevant: 59594: close(11) = 0 (0x0) 59594: unlink("/var/cache/cups/job.cache.O") = 0 (0x0) 59594: rename("/var/cache/cups/job.cache","/var/cache/cups/job.cache.O") = 0 (0x0) 59594: rename("/var/cache/cups/job.cache.N","/var/cache/cups/job.cache") = 0 (0x0) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] c"...,89) = 89 (0x59) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] ["...,67) = 67 (0x43) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] c"...,53) = 53 (0x35) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] c"...,89) = 89 (0x59) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,49) = 49 (0x31) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,48) = 48 (0x30) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,53) = 53 (0x35) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,50) = 50 (0x32) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,69) = 69 (0x45) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,68) = 68 (0x44) 59594: write(5,"D [16/Jun/2020:11:43:03 +0200] R"...,69) = 69 (0x45) 59594: kevent(3,0x0,0,{ },469674,{ 11.000000000 }) = 0 (0x0) 59594: write(5,"D [16/Jun/2020:11:43:14 +0200] ["...,67) = 67 (0x43) 59594: write(5,"D [16/Jun/2020:11:43:14 +0200] c"...,53) = 53 (0x35) 59594: write(5,"D [16/Jun/2020:11:43:14 +0200] c"...,92) = 92 (0x5c) ...skipping... 70204: recvfrom(3,"!",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\^P",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"time-at-creation",16,0,NULL,0x0) = 16 (0x10) 70204: recvfrom(3,"\0\^D",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"^\M-g\^Z,",4,0,NULL,0x0) = 4 (0x4) 70204: recvfrom(3,"!",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\^R",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"time-at-processing",18,0,NULL,0x0) = 18 (0x12) 70204: recvfrom(3,"\0\^D",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"^\M-h_8",4,0,NULL,0x0) = 4 (0x4) 70204: recvfrom(3,"!",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\^F",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"job-id",6,0,NULL,0x0) = 6 (0x6) 70204: recvfrom(3,"\0\^D",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"\0\0\^D.",4,0,NULL,0x0) = 4 (0x4) 70204: recvfrom(3,"#",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\t",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"job-state",9,0,NULL,0x0) = 9 (0x9) 70204: recvfrom(3,"\0\^D",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"\0\0\0\^C",4,0,NULL,0x0) = 4 (0x4) 70204: recvfrom(3,"!",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\^Y",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"job-impressions-completed",25,0,NULL,0x0) = 25 (0x19) 70204: recvfrom(3,"\0\^D",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"\0\0\0\n",4,0,NULL,0x0) = 4 (0x4) 70204: recvfrom(3,"!",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\f",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"job-k-octets",12,0,NULL,0x0) = 12 (0xc) 70204: recvfrom(3,"\0\^D",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"\0\0\0\^A",4,0,NULL,0x0) = 4 (0x4) 70204: recvfrom(3,"A",1,0,NULL,0x0) = 1 (0x1) 70204: recvfrom(3,"\0\^Y",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"job-printer-state-message",25,0,NULL,0x0) = 25 (0x19) 70204: recvfrom(3,"\0\^N",2,0,NULL,0x0) = 2 (0x2) 70204: recvfrom(3,"Backend failed",14,0,NULL,0x0) = 14 (0xe) 70204: recvfrom(3,"\^C",1,0,NULL,0x0) = 1 (0x1) 70204: write(2,"DEBUG: cgiClearVariables called."...,33) = 33 (0x21) 59594: kevent(3,0x0,0,{ 9,EVFILT_READ,0x0,0,0x21,0x803ed55e0 },469674,{ 1.000000000 }) = 1 (0x1) 70204: write(2,"cgiSetVariable: SECTION="printer"...,35) = 35 (0x23) 59594: read(9,"DEBUG: cgiClearVariables called."...,2047) = 68 (0x44) 70204: write(2,"cgiSetVariable: TOTAL="1"\n",26) = 26 (0x1a) 59594: write(5,"D [16/Jun/2020:11:43:18 +0200] ["...,63) = 63 (0x3f) 70204: write(2,"DEBUG2: cgiSetIPPObjectVars(obj="...,73) = 73 (0x49) 59594: write(5,"D [16/Jun/2020:11:43:18 +0200] ["...,74) = 74 (0x4a) 70204: write(2,"cgiSetVariable: SERVER_NAME="172"...,41) = 41 (0x29) 59594: write(5,"D [16/Jun/2020:11:43:18 +0200] ["...,67) = 67 (0x43) 70204: write(2,"cgiSetVariable: REMOTE_USER="roo"...,35) = 35 (0x23) 59594: write(5,"D [16/Jun/2020:11:43:18 +0200] c"...,53) = 53 (0x35) 70204: write(2,"cgiSetVariable: CUPS_VERSION="CU"...,44) = 44 (0x2c) 59594: write(5,"D [16/Jun/2020:11:43:18 +0200] c"...,130) = 130 (0x82) 70204: open("/usr/share/locale/en_US.UTF8/LC_TIME",O_RDONLY|O_CLOEXEC,015533671400) ERR#2 'No such file or directory' 59594: kevent(3,0x0,0,{ 9,EVFILT_READ,0x0,0,0xdb,0x803ed55e0 },469674,{ 1.000000000 }) = 1 (0x1) 70204: write(2,"DEBUG: cgiSetArray: job_printer_"...,59) = 59 (0x3b) 59594: read(9,"cgiSetVariable: TOTAL="1"\nDEBUG"...,2047) = 278 (0x116) 70204: write(2,"DEBUG: cgiSetArray: job_printer_"...,68) = 68 (0x44) 59594: write(5,"D [16/Jun/2020:11:43:18 +0200] ["...,65) = 65 (0x41)