I'm just testing setting up a printserver with 4.14. I use both, the Sernet-packages and the packages from Louis van Belle on debian buster. I have three print server running: one with Sernet 4.14rc2 one with Louis 4.14rc1 one with Louis 4.13 All set up exactly the same with this smb.conf: -------- [global] workgroup = EXAMPLE realm = EXAMPLE.NET security = ADS winbind refresh tickets = Yes winbind use default domain = yes template shell = /bin/bash idmap config * : range = 10000 - 19999 idmap config EXAMPLE : backend = rid idmap config EXAMPLE : range = 10000000 - 19999999 [print$] path = /var/lib/samba/printers comment = printer drivers create mask = 0775 inherit permissions = yes read only = no [printers] path = /var/spool/samba comment = spooling directory create mask = 0700 browsable = no read only = no printable = yes -------- I set permission for all systems: -------- chgrp -R 'domain admins' /var/lib/samba/printers/ chmod -R 775 /var/lib/samba/printers/ net rpc rights grant 'example\Domain Admins' SePrintOperatorPrivilege -k -S <print-server-name> -------- Set up Cups with two printers an I can see the printers: ------- root@ps1:~# smbclient -L ps1 -k Sharename Type Comment --------- ---- ------- print$ Disk printer drivers IPC$ IPC IPC Service (Samba 4.14.0rc2-SerNet-Debian-1.buster) HL3230-ps1 Printer HL3230-ps1 HP6-ps1 Printer HP6-ps1 SMB1 disabled -- no workgroup available ------- I login at my windows-system with my domain-admin starting the "print management app" Add all three print server. I can see the printers for each print server (every printer server is showing it's own printers). Then I click on "drivers" to add a new signed driver. Widows is showing the progress bar for uploading the driver to the print server. On both 4.14 print servers the directory /var/lib/samba/printers/x86/3 is created but empty, only the one with 4.13 has the files for the driver. No error on the windows-system, no error on both of the Samba print servers. The app is showing the driver as present! But there are no files on the print server, only on the 4.13 system.
@Stefan: would you be able to provide 4.13 and 4.14rc "log level = 10" logs captured across the driver upload attempt?
Adding the driver files log level set to 10: [2021/02/08 04:49:55.289195, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x31b len 91 (num_fds:0) from 1539 [2021/02/08 04:49:55.289220, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) notifyd_trigger: Got trigger_msg action=1, filter=2, path=/var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8} [2021/02/08 04:49:55.289236, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var [2021/02/08 04:49:55.289247, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib [2021/02/08 04:49:55.289255, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba [2021/02/08 04:49:55.289263, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers [2021/02/08 04:49:55.289271, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64 [2021/02/08 04:49:55.297774, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x31b len 103 (num_fds:0) from 1539 [2021/02/08 04:49:55.297794, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) notifyd_trigger: Got trigger_msg action=1, filter=1, path=/var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8}/SET3876.tmp [2021/02/08 04:49:55.297804, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var [2021/02/08 04:49:55.297812, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib [2021/02/08 04:49:55.297820, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba [2021/02/08 04:49:55.297827, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers [2021/02/08 04:49:55.297835, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64 [2021/02/08 04:49:55.297843, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8} [2021/02/08 04:49:55.302435, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x31b len 103 (num_fds:0) from 1539 [2021/02/08 04:49:55.302454, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) notifyd_trigger: Got trigger_msg action=3, filter=4, path=/var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8}/SET3876.tmp [2021/02/08 04:49:55.302463, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var [2021/02/08 04:49:55.302471, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib [2021/02/08 04:49:55.302482, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba [2021/02/08 04:49:55.302490, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers [2021/02/08 04:49:55.302497, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64 [2021/02/08 04:49:55.302504, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8} [2021/02/08 04:49:55.302768, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x31b len 103 (num_fds:0) from 1539 [2021/02/08 04:49:55.302783, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) notifyd_trigger: Got trigger_msg action=3, filter=0, path=/var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8}/SET3876.tmp [2021/02/08 04:49:55.302792, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var [2021/02/08 04:49:55.302800, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib [2021/02/08 04:49:55.302807, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba [2021/02/08 04:49:55.302814, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers [2021/02/08 04:49:55.302821, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64 [2021/02/08 04:49:55.302828, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8} [2021/02/08 04:49:55.312408, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x31b len 103 (num_fds:0) from 1539 [2021/02/08 04:49:55.312428, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) notifyd_trigger: Got trigger_msg action=2, filter=1, path=/var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8}/SET3876.tmp [2021/02/08 04:49:55.312437, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var [2021/02/08 04:49:55.312446, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib [2021/02/08 04:49:55.312453, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba [2021/02/08 04:49:55.312460, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers [2021/02/08 04:49:55.312467, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64 [2021/02/08 04:49:55.312474, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8} [2021/02/08 04:49:55.314582, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x31b len 103 (num_fds:0) from 1539 [2021/02/08 04:49:55.314602, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:651(notifyd_trigger) notifyd_trigger: Got trigger_msg action=1, filter=1, path=/var/lib/samba/printers/x64/{829226F7-38E1-47F4-AD53-A59E75E5EEA8}/SET3876.tmp [2021/02/08 04:49:55.314611, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var [2021/02/08 04:49:55.314620, 10, pid=1527, effective(0, 0), real(0, 0)] ../../source3/smbd/notifyd/notifyd.c:667(notifyd_trigger) notifyd_trigger: Trying path /var/lib [2021/02/08 04:50:00.419537, 10, pid=1529, effective(0, 0), real(0, 0)] ../../source3/lib/messages.c:428(messaging_recv_cb) messaging_recv_cb: Received message 0x203 len 25 (num_fds:0) from 1539 [2021/02/08 04:50:00.419606, 10, pid=1529, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/spoolss/srv_spoolss_nt.c:1518(do_drv_upgrade_printer) do_drv_upgrade_printer: Got message for new driver [HP Universal Printing PS] [2021/02/08 04:50:00.419665, 5, pid=1529, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_ncacn_np.c:258(make_internal_ncacn_conn) make_internal_ncacn_conn: Create pipe requested winreg [2021/02/08 04:50:00.419745, 4, pid=1529, effective(0, 0), real(0, 0), class=rpc_srv] ../../source3/rpc_server/rpc_ncacn_np.c:304(make_internal_ncacn_conn) Created internal pipe winreg [2021/02/08 04:50:00.419838, 1, pid=1529, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:478(ndr_print_function_debug) winreg_OpenHKLM: struct winreg_OpenHKLM in: struct winreg_OpenHKLM system_name : NULL access_mask : 0x02000000 (33554432) 0: KEY_QUERY_VALUE 0: KEY_SET_VALUE 0: KEY_CREATE_SUB_KEY 0: KEY_ENUMERATE_SUB_KEYS 0: KEY_NOTIFY 0: KEY_CREATE_LINK 0: KEY_WOW64_64KEY 0: KEY_WOW64_32KEY [2021/02/08 04:50:00.419950, 7, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_api.c:143(regkey_open_onelevel) regkey_open_onelevel: name = [HKLM] [2021/02/08 04:50:00.419995, 4, pid=1529, effective(0, 0), real(0, 0)] ../../source3/smbd/sec_ctx.c:216(push_sec_ctx) push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1 [2021/02/08 04:50:00.420022, 4, pid=1529, effective(0, 0), real(0, 0)] ../../source3/smbd/uid.c:562(push_conn_ctx) push_conn_ctx(0) : conn_ctx_stack_ndx = 0 [2021/02/08 04:50:00.420045, 4, pid=1529, effective(0, 0), real(0, 0)] ../../source3/smbd/sec_ctx.c:320(set_sec_ctx_internal) setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1 [2021/02/08 04:50:00.420067, 5, pid=1529, effective(0, 0), real(0, 0)] ../../libcli/security/security_token.c:47(security_token_debug) Security token: (NULL) [2021/02/08 04:50:00.420090, 5, pid=1529, effective(0, 0), real(0, 0)] ../../source3/auth/token_util.c:874(debug_unix_user_token) UNIX token of user 0 Primary group is 0 and contains 0 supplementary groups [2021/02/08 04:50:00.420218, 4, pid=1529, effective(0, 0), real(0, 0)] ../../source3/smbd/sec_ctx.c:438(pop_sec_ctx) pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0 [2021/02/08 04:50:00.420250, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_backend_db.c:887(regdb_open) regdb_open: registry db opened. refcount reset (1) [2021/02/08 04:50:00.420278, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_cachehook.c:125(reghook_cache_find) reghook_cache_find: Searching for keyname [\HKLM] [2021/02/08 04:50:00.420302, 10, pid=1529, effective(0, 0), real(0, 0)] ../../source3/lib/adt_tree.c:367(pathtree_find) pathtree_find: Enter [\HKLM] [2021/02/08 04:50:00.420340, 10, pid=1529, effective(0, 0), real(0, 0)] ../../source3/lib/adt_tree.c:440(pathtree_find) pathtree_find: Exit [2021/02/08 04:50:00.420362, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_cachehook.c:130(reghook_cache_find) reghook_cache_find: found ops 0x7fdd6cfbb020 for key [\HKLM] [2021/02/08 04:50:00.420426, 1, pid=1529, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:478(ndr_print_function_debug) winreg_OpenHKLM: struct winreg_OpenHKLM out: struct winreg_OpenHKLM handle : * handle: struct policy_handle handle_type : 0x00000001 (1) uuid : cdafa9b6-58a5-480d-9bd4-6f9c16f77d55 result : WERR_OK [2021/02/08 04:50:00.420552, 1, pid=1529, effective(0, 0), real(0, 0), class=rpc_parse] ../../librpc/ndr/ndr.c:478(ndr_print_function_debug) winreg_OpenKey: struct winreg_OpenKey in: struct winreg_OpenKey parent_handle : * parent_handle: struct policy_handle handle_type : 0x00000001 (1) uuid : cdafa9b6-58a5-480d-9bd4-6f9c16f77d55 keyname: struct winreg_String name_len : 0x0086 (134) name_size : 0x0086 (134) name : * name : 'SOFTWARE\Microsoft\Windows NT\CurrentVersion\Print\Printers\HL3230' options : 0x00000000 (0) 0: REG_OPTION_VOLATILE 0: REG_OPTION_CREATE_LINK 0: REG_OPTION_BACKUP_RESTORE 0: REG_OPTION_OPEN_LINK access_mask : 0x02000000 (33554432) 0: KEY_QUERY_VALUE 0: KEY_SET_VALUE 0: KEY_CREATE_SUB_KEY 0: KEY_ENUMERATE_SUB_KEYS 0: KEY_NOTIFY 0: KEY_CREATE_LINK 0: KEY_WOW64_64KEY 0: KEY_WOW64_32KEY [2021/02/08 04:50:00.420758, 7, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_api.c:143(regkey_open_onelevel) regkey_open_onelevel: name = [SOFTWARE] [2021/02/08 04:50:00.420784, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_backend_db.c:859(regdb_open) regdb_open: incrementing refcount (1->2) [2021/02/08 04:50:00.420811, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_cachehook.c:125(reghook_cache_find) reghook_cache_find: Searching for keyname [\HKLM\SOFTWARE] [2021/02/08 04:50:00.420834, 10, pid=1529, effective(0, 0), real(0, 0)] ../../source3/lib/adt_tree.c:367(pathtree_find) pathtree_find: Enter [\HKLM\SOFTWARE] [2021/02/08 04:50:00.420859, 10, pid=1529, effective(0, 0), real(0, 0)] ../../source3/lib/adt_tree.c:440(pathtree_find) pathtree_find: Exit [2021/02/08 04:50:00.420881, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_cachehook.c:130(reghook_cache_find) reghook_cache_find: found ops 0x7fdd6cfbb020 for key [\HKLM\SOFTWARE] [2021/02/08 04:50:00.420933, 7, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_api.c:143(regkey_open_onelevel) regkey_open_onelevel: name = [Microsoft] [2021/02/08 04:50:00.420958, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_backend_db.c:859(regdb_open) regdb_open: incrementing refcount (2->3) [2021/02/08 04:50:00.420983, 10, pid=1529, effective(0, 0), real(0, 0), class=registry] ../../source3/registry/reg_cachehook.c:125(reghook_cache_find) reghook_cache_find: Searching for keyname [\HKLM\SOFTWARE\Microsoft]
(In reply to Stefan Kania from comment #2) Are you sure that's all? I would think the log should be bigger then what you pasted. *scratches head* I bet Jeremy and I broke this with the VFS changes.
Yes, I started "tail -n /var/log/log.smbd" with "log level = 10 " in smb.conf. Then I chose the driver to upload (in Windows) and before I pressed OK to finally upload the driver, I cleared the output from the "tail -f". Then I pressed "OK" and what you see is all I get.
hmm, yeah this log does appear truncated. I'd expect to see a AddPrinterDriver[Ex] call somewhere. Could logrotate or something be getting in the way?
I opened the log with "tail -f" and copied everything from the console that appears on the screen. I did not close the log, nothing. So no logrotate could remove something. I did it again with the same result. But that's exactly what I said. Windows is showing the window copying the files, no message at all. An message on the print server and the directory /var/lib/samba/printers/x86/3 was created but empty.
(In reply to Stefan Kania from comment #6) well, if "max log size" is in effect and gets triggered, smbd will close the logfile you're polling and open a new one and use that instead, causing tail -f to miss all that. Can you check whether this could be happening? If not, I guess a network trace would also be good to get a high level overview of what's going on.
Created attachment 16436 [details] logfile log.smbd This is the logfile with log lecel set to 10
Created attachment 16437 [details] logfile log.smbd.old The second log file
The two logfiles where generated only during the process of adding the printer driver
(In reply to Stefan Kania from comment #10) Thanks. I don't see any obvious unexpected errors with emacs smb-logmode. *scratches head*
Created attachment 16439 [details] vagrant environment to test This tar.gz file is my Vagrant environment. If you want, you can test it with VirtualBox. The Vagrantfile will create DC (4.14) one host "printserver" with 4.14 and one "printserver13" with 4.13. just join a windows-system, creat a cups-printer and you can test it.
Created attachment 16452 [details] Possible patch for master and 4.14
This bug was referenced in samba master: 8c1fd86db873f0326faf1cefa731a03709f8ac7f 70063c523bff5e471eac2b011b243c5aa0c4bee1 718f7b1a84f1c6eb35d52232a8573370f45add56
Created attachment 16465 [details] Patch for 4.14 cherry-picked from master
Comment on attachment 16465 [details] Patch for 4.14 cherry-picked from master LGTM
Karolin, please add to v4-14, thanks!
(In reply to Guenther Deschner from comment #17) Pushed to autobuild-v4-14-test.
This bug was referenced in samba v4-14-test: 5b1a5b776a7bed76695599211397469666fb2142 b30a1950e260fb7fd098da2deff608b7c505ef0d 1f520ec35e151bcde8103ba6cfbdced67b242d0a
Pushed to v4-14-test. Closing out bug report. Thanks!
This bug was referenced in samba v4-14-stable (Release samba-4.14.0rc4): 5b1a5b776a7bed76695599211397469666fb2142 b30a1950e260fb7fd098da2deff608b7c505ef0d 1f520ec35e151bcde8103ba6cfbdced67b242d0a