Bug 1706090
Summary: | Cannot print to SMB printer | ||
---|---|---|---|
Product: | [Fedora] Fedora | Reporter: | Stephen So <steve8988> |
Component: | samba | Assignee: | Guenther Deschner <gdeschner> |
Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
Severity: | high | Docs Contact: | |
Priority: | unspecified | ||
Version: | 30 | CC: | abokovoy, anoopcs, asn, gdeschner, guina, joukj, jpopelka, jrivera, jstephen, lmohanty, madam, ngaywood, paullee0, sbose, ssorce, twaugh, zdohnal |
Target Milestone: | --- | ||
Target Release: | --- | ||
Hardware: | x86_64 | ||
OS: | Linux | ||
Whiteboard: | |||
Fixed In Version: | samba-4.10.5-1.fc30 | Doc Type: | If docs needed, set a value |
Doc Text: | Story Points: | --- | |
Clone Of: | Environment: | ||
Last Closed: | 2019-07-06 04:08:56 UTC | Type: | Bug |
Regression: | --- | Mount Type: | --- |
Documentation: | --- | CRM: | |
Verified Versions: | Category: | --- | |
oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
Cloudforms Team: | --- | Target Upstream Version: | |
Embargoed: | |||
Attachments: |
Description
Stephen So
2019-05-03 14:21:21 UTC
Printing using smbspool also works fine, i.e. smbspool smb://user:password@printer_address/Find-Me-Print 1 1 0 1 1 file.ps Got a simmilar problem, also after the upgrade to F30. In my case it keeps telling me that I need "credentials" to print, although they are hard-coded in the printers.conf file. A complete "fresh" installation of F30 gave the same problem. I reinstalled F29 and the problem was gone. I'm going to create an installation of F30 in vbox, so that I can do some experiments. Jouk Hi! thank you for reporting the issue! According CUPS upstream ( https://github.com/apple/cups/issues/5573 ), samba people should take a look on the issue. My guess would be that this is fixed with https://bugzilla.samba.org/show_bug.cgi?id=13939 Please enable *debug* logging of CUPS and then reproduce the issue and provide the cups log. journalctl -f -u cups.service should normally give you the log. Here is the debug log after I printed a test page from system-config-printer -- Logs begin at Tue 2019-04-23 23:44:00 AEST. -- May 14 10:52:41 corei5 cupsd[13403]: Starting renderer with command: \"printf \"%%!PS-Adobe-3.0 May 14 10:52:41 corei5 cupsd[13403]: %%%%Title: (Test Page) May 14 10:52:41 corei5 cupsd[13403]: %% May 14 10:52:41 corei5 cupsd[13403]: %%\\n/lppswd()def\\n/dspswd()def\\n/usrcode()def\\nmark\\n/usrcode where{pop}{/usrcode()def}ifelse\\n(root) usrcode (20`date +%y%m%d%R | sed \'s/://\'`) {setuserinfo} stopped\\ncleartomark\\nmark {\\n<<\\n /JobType 0\\n /JobInfo <<\\n /UserID (root)\\n /Time (20`date +%y%m%d%R | sed \'s/://\'`)\\n /HostLoginName (root)\\n /HostName (corei5)\\n >>\\n>> /RDeviceProcSet /ProcSet findresource /SetJobType get exec\\n}stopped cleartomark\\n<</OutputType null>>setpagedevice\\nuserdict /RPS_BPdict 2 dict put\\nuserdict /RPS_BPdict get begin /RPS_BP_MEDIAPOSITION null def end\\nuserdict /RPS_BPdict get begin\\n/RPS_BP_MEDIATYPE (Auto) def end\\n<<\\n/BannerPageMode false\\n/MediaPosition null\\n/MediaType null\\n>>\\n/RDeviceProcSet \\n/ProcSet findresource \\n/SetBannerPage get exec\\n\"%%%%; cat;\" May 14 10:52:41 corei5 cupsd[13403]: Starting process \"kid3\" (generation 1) May 14 10:52:41 corei5 cupsd[13403]: Starting process \"kid4\" (generation 2) May 14 10:52:41 corei5 cupsd[13403]: Starting process \"renderer\" (generation 2) May 14 10:52:41 corei5 cupsd[13403]: JCL: \033%-12345X@PJL May 14 10:52:41 corei5 cupsd[13403]: <job data> May 14 10:52:42 corei5 cupsd[13403]: Expiring subscriptions... May 14 10:53:11 corei5 cupsd[13403]: Saving job.cache... May 14 10:53:11 corei5 cupsd[13403]: Saving subscriptions.conf... May 14 10:53:11 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Printing jobs", busy="Printing jobs and dirty files" May 14 10:53:11 corei5 cupsd[13403]: Expiring subscriptions... May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Active clients and printing jobs", busy="Printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Server address is "/var/run/cups/cups.sock". May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Accepted from localhost (Domain) May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Waiting for request. May 14 10:53:12 corei5 cupsd[13403]: Expiring subscriptions... May 14 10:53:12 corei5 cupsd[13403]: [Client 5] POST / HTTP/1.1 May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Active clients and printing jobs", busy="Active clients and printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Read: status=200, state=6 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] No authentication data provided. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] 2.0 CUPS-Get-Default 1 May 14 10:53:12 corei5 cupsd[13403]: CUPS-Get-Default May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Content-Length: 1323 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] con->http=0x557dbe990370 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1323, response=0x557dbe913c70(IPP_STATE_DATA), pipe_pid=0, file=-1 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] bytes=0, http_state=0, data_remaining=1323 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Flushing write buffer. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] New state is HTTP_STATE_WAITING May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Waiting for request. May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Printing jobs", busy="Active clients and printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] POST / HTTP/1.1 May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Active clients and printing jobs", busy="Printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Read: status=200, state=6 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] No authentication data provided. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] 2.0 Get-Printer-Attributes 2 May 14 10:53:12 corei5 cupsd[13403]: Get-Printer-Attributes ipp://localhost:631/printers/- May 14 10:53:12 corei5 cupsd[13403]: Get-Printer-Attributes client-error-not-found: The printer or class does not exist. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Returning IPP client-error-not-found for Get-Printer-Attributes (ipp://localhost:631/printers/-) from localhost. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Content-Length: 130 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] con->http=0x557dbe990370 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=130, response=0x557dbe960a00(IPP_STATE_DATA), pipe_pid=0, file=-1 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] bytes=0, http_state=0, data_remaining=130 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Flushing write buffer. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] New state is HTTP_STATE_WAITING May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Waiting for request. May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Printing jobs", busy="Active clients and printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] POST / HTTP/1.1 May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Active clients and printing jobs", busy="Printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Read: status=200, state=6 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] No authentication data provided. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] 2.0 CUPS-Get-Printers 3 May 14 10:53:12 corei5 cupsd[13403]: CUPS-Get-Printers May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Returning IPP successful-ok for CUPS-Get-Printers (no URI) from localhost. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Content-Length: 1323 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] con->http=0x557dbe990370 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=1323, response=0x557dbe913c70(IPP_STATE_DATA), pipe_pid=0, file=-1 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] bytes=0, http_state=0, data_remaining=1323 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Flushing write buffer. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] New state is HTTP_STATE_WAITING May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Waiting for request. May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Printing jobs", busy="Active clients and printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] POST / HTTP/1.1 May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Active clients and printing jobs", busy="Printing jobs" May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Read: status=200, state=6 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] No authentication data provided. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] 2.0 CUPS-Get-Default 4 May 14 10:53:12 corei5 cupsd[13403]: CUPS-Get-Default May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Returning IPP successful-ok for CUPS-Get-Default (no URI) from localhost. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Content-Length: 13916 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdSendHeader: code=200, type="application/ipp", auth_type=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] con->http=0x557dbe990370 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] cupsdWriteClient error=0, used=0, state=HTTP_STATE_POST_SEND, data_encoding=HTTP_ENCODING_LENGTH, data_remaining=13916, response=0x557dbe960a00(IPP_STATE_DATA), pipe_pid=0, file=-1 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Writing IPP response, ipp_state=IPP_STATE_DATA, old wused=0, new wused=0 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] bytes=0, http_state=0, data_remaining=13916 May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Flushing write buffer. May 14 10:53:12 corei5 cupsd[13403]: [Client 5] New state is HTTP_STATE_WAITING May 14 10:53:12 corei5 cupsd[13403]: [Client 5] Waiting for request. May 14 10:53:12 corei5 cupsd[13403]: cupsdSetBusyState: newbusy="Printing jobs", busy="Active clients and printing jobs" When I try to print a test page from the cups web interface, I get the following message "Session setup failed: NT_STATUS_NOT_SUPPORTED" So it is a samba issue? Stephen, thank you for providing the log, but unfortunately it is cropped - I do not see the whole job. Please follow these steps: 1) $ journalctl -f -u cups > cups_whole_log (in other terminal, your_print_queue_name is the name of printer, which it has in system-config-printer) 2) $ lp -d <your_print_queue_name> /etc/fstab (you will see a string in the terminal, which will contains string alike your_print_queue_name-NNN, where NNN are numbers. You will need those numbers.) 3) wait until job is finished - you can check it by '$ lpstat -o <your_print_queue_name>' - if it will take too long (f.e. 1 minute), cancel the job by 'cancel <NNN>', where <NNN> are numbers from lp output 4) stop the journalctl command - just press ctrl+c in terminal where it is running. 5) $ journalctl -u cups JID=<NNN> > cups_job_log 6) please attach both files: cups_whole_log, cups_job_log to the bugzilla. Until we find out more info, let's stay in cups component. I already have some fixes, but I need logs to understand what CUPS is doing on different hosts as it looks like there are different configurations. So different routes. You can use cupsctl --debug-logging to turn on debug logging ... Created attachment 1568723 [details]
Requested cups_whole_log file
Here is the requested cups_whole_log file
Created attachment 1568725 [details]
Requested cups_job_log
Samba connection messages: May 15 09:57:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:57:14 corei5 cupsd[811]: Set job-printer-state-message to "Session setup failed: NT_STATUS_NOT_SUPPORTED", current level=ERROR May 15 09:57:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) . . . May 15 09:57:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_INVALID_PARAMETER May 15 09:57:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_INVALID_PARAMETER [c000000d]) May 15 09:57:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:57:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:57:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:57:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:57:14 corei5 cupsd[811]: Unable to connect to CIFS host, will retry in 60 seconds... . . . May 15 09:58:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:58:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:58:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_INVALID_PARAMETER May 15 09:58:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_INVALID_PARAMETER [c000000d]) May 15 09:58:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:58:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:58:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:58:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:58:14 corei5 cupsd[811]: Unable to connect to CIFS host, will retry in 60 seconds... May 15 09:59:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:59:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:59:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_INVALID_PARAMETER May 15 09:59:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_INVALID_PARAMETER [c000000d]) May 15 09:59:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:59:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:59:14 corei5 cupsd[811]: Session setup failed: NT_STATUS_NOT_SUPPORTED May 15 09:59:14 corei5 cupsd[811]: get_exit_code(cli=0x555e4e7b5c20, nt_status=NT_STATUS_NOT_SUPPORTED [c00000bb]) May 15 09:59:14 corei5 cupsd[811]: Unable to connect to CIFS host, will retry in 60 seconds... May 15 09:59:21 corei5 cupsd[811]: time-at-completed=1557878361 May 15 09:59:21 corei5 cupsd[811]: Job canceled by \"root\" May 15 09:59:21 corei5 cupsd[811]: PID 1131 (/usr/lib/cups/backend/smb) was terminated normally with signal 15. According other job log it seems device uri nor environment provide the credentials - I'll create samba scratch build based on Andreas' link to samba upstream. Stephen, would you mind testing it if it helps for you? Yes, I'm more than happy to test it, if you can provide me with the rpms. Here are the rpms https://koji.fedoraproject.org/koji/taskinfo?taskID=34866229 Created attachment 1568810 [details]
cups_whole_log (after installing samba upstream)
Unfortunately, it still doesn't work. Here are the logs.
Created attachment 1568811 [details]
cups_job_log (after installing samba upstream)
Still the same errors from samba, even by applying https://attachments.samba.org/attachment.cgi?id=15137 . Andreas, I'll move it to samba for more investigation. Zdenek, yeah this is still work in progress, see https://git.samba.org/?p=asn/samba.git;a=shortlog;h=refs/heads/master-smbspool Perhaps a patch for this now? https://bugzilla.samba.org/show_bug.cgi?id=13939#c22 FEDORA-2019-8015e5dc40 has been submitted as an update to Fedora 30. https://bodhi.fedoraproject.org/updates/FEDORA-2019-8015e5dc40 Created attachment 1582978 [details] cups_log (after installing samba-4.10.5-1.fc30) I've updated to the latest samba build from koji - https://koji.fedoraproject.org/koji/buildinfo?buildID=1291125 Getting a different problem now. After printing the cups test page, I am getting an "Idle - Filter failed" as the printer state. I've uploaded the cups_log. There seems to be a "Broken pipe during fwrite" message. Jun 21 11:13:09 corei5 cupsd[5528]: renderer exited with status 141 Jun 21 11:13:09 corei5 cupsd[5528]: A filter used in addition to the renderer itself may have failed.Process is dying with \"Encountered error Broken pipe during fwrite\", exit stat 1 Jun 21 11:13:09 corei5 cupsd[5528]: Cleaning up... Jun 21 11:13:09 corei5 cupsd[5528]: Killing kid3 Jun 21 11:13:09 corei5 cupsd[5528]: Process is dying with \"Caught termination signal: Job canceled Jun 21 11:13:09 corei5 cupsd[5528]: \", exit stat 0 Jun 21 11:13:09 corei5 cupsd[5528]: Cleaning up... Jun 21 11:13:09 corei5 cupsd[5528]: Killing kid4 Jun 21 11:13:10 corei5 cupsd[5528]: Expiring subscriptions... Jun 21 11:13:17 corei5 cupsd[5528]: Expiring subscriptions... Jun 21 11:13:17 corei5 cupsd[5528]: PID 5585 (/usr/lib/cups/filter/foomatic-rip) stopped with status 1. Looks like the filter failed to render the page. smbspool is not involved in this. I only see in the logs: kerberos_ccache_is_valid: Failed to get default principal from ccache: KCM: which means the user doesn't have a Kerberos ticket and can't authenticate. (In reply to Andreas Schneider from comment #25) > I only see in the logs: > > kerberos_ccache_is_valid: Failed to get default principal from ccache: KCM: > > > which means the user doesn't have a Kerberos ticket and can't authenticate. One thing I noticed different is in my /etc/cups/printers.conf file, there is a "AuthInfoRequired none" line, even though the DeviceURI has my username and password. I tried adding another samba printer and it also has this line in it too. When I checked my printers.conf file from the previous Fedora 28, it had "AuthInfoRequired username,password", while in Fedora 29, it didn't even have a "AuthInfoRequired" line. Could this explain wny the print jobs are always "held for authentication"? Yes, this needs to be set to: AuthInfoRequired username,password samba-4.10.5-1.fc30 has been pushed to the Fedora 30 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2019-8015e5dc40 samba-4.10.5-1.fc30 has been pushed to the Fedora 30 stable repository. If problems still persist, please make note of it in this bug report. Similar bug in ? https://bugzilla.redhat.com/show_bug.cgi?id=1700791 In my case, "Required Credential to print" appears in notification area. Procedures: 1. Install F30 2. Install Printer, searching the local network area, add the printer 3. Print to the network printer 4. "Required Credential to print" F29 has no such problem. |