Bug 14895 - Log filling up with spam about printing despite it being disabled
Summary: Log filling up with spam about printing despite it being disabled
Status: RESOLVED FIXED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: Printing (show other bugs)
Version: 4.13.5
Hardware: x64 Linux
: P5 minor (vote)
Target Milestone: ---
Assignee: David Disseldorp
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-11-06 13:41 UTC by Nate Stuyvesant
Modified: 2021-11-11 13:51 UTC (History)
1 user (show)

See Also:


Attachments
proposed fix (1.33 KB, patch)
2021-11-08 11:56 UTC, David Disseldorp
asn: review+
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Nate Stuyvesant 2021-11-06 13:41:54 UTC
Seeing entries like this in log.smbd (they are filling up my log file)...
[2021/11/06 08:55:29.716569,  1] ../../source3/printing/printer_list.c:234(printer_list_get_las
t_refresh)
  Failed to fetch record!
[2021/11/06 08:55:29.716790,  1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printe
rs)
  pcap cache not loaded

I am only using Samba for SMB file serving. Printing is disabled. Here's my smb.conf...

[global]
allow dns updates = disabled
bind interfaces only = Yes
client min protocol = SMB3_02
dcerpc endpoint servers = rpcecho
delete veto files = Yes
disable netbios = Yes
disable spoolss = Yes
dns forwarder = 192.168.1.1
dns proxy = No
# Do not need core dumps (but Samba docs say to leave it alone)
;enable core files = No
enhanced browsing = No
# Next line requires catia (but is it needed if no Windows clients?)
fruit:encoding = native
fruit:metadata = stream
fruit:model = Macmini7
# Not using NFS...
fruit:nfs_aces = No
# Next line needed for ZFS
fruit:resource = xattr
fruit:zero_file_id = Yes
fstype = Samba
host msdfs = No
inherit acls = Yes
inherit permissions = Yes
interfaces = lan
lm announce = No
load printers = No
log file = /var/log/samba/log.smbd
# Change next one to zero to speed things up
log level = 1
logging = file
max log size = 10000
mdns name = mdns
multicast dns register = No
name resolve order = host bcast
pam password change = Yes
panic action = /usr/share/samba/panic-action %d
passwd chat = "*New Password:*" %n\n "*Reenter New Password:*" %n\n "*Password changed.*"
passwd program = /usr/bin/passwd %u
printcap cache time = 0
printcap name = /dev/null
printing = bsd
restrict anonymous = 2
rpc_server:epmapper = disabled
rpc_server:winreg = disabled
rpc_server:lsarpc = disabled
rpc_server:samr = disabled
rpc_server:netlogon = disabled
rpc_server:netdfs = disabled
rpc_server:dssetup = disabled
rpc_server:wkssvc = disabled
rpc_server:spoolss = disabled
rpc_server:svcctl = disabled
rpc_server:ntsvcs = disabled
rpc_server:eventlog = disabled
rpc_server:initshutdown = disabled
rpc_server:mdssvc = disabled
server max protocol = SMB3_11
server min protocol = SMB3_02
# Next one is experimental
server multi channel support = Yes
server role = standalone server
server services = rpc, smb
server string = %h server (Samba 4.13.5, Ubuntu 21.10)
show add printer wizard = No
smb ports = 445
unix password sync = Yes
use sendfile = Yes
veto files = /._*/.DS_Store/
vfs objects = catia fruit streams_xattr

[homes]
browseable = No
comment = Home Directory
fruit:time machine = No
guest ok = No
path = %H
spotlight = Yes
spotlight backend = elasticsearch
valid users = %S
writable = Yes

[Backup]
comment = Time Machine
fruit:time machine = Yes
guest ok = No
path = /external/%U
spotlight = No
valid users = %U
writable = Yes
Comment 1 David Disseldorp 2021-11-07 21:57:30 UTC
This should go away once you set:
  printcap cache time = 0

Printing currently requires way too many knobs to toggle it on or off, sorry.
Comment 2 David Disseldorp 2021-11-07 22:20:37 UTC
(In reply to David Disseldorp from comment #1)
> This should go away once you set:
>   printcap cache time = 0

Hmmf okay, ignore this, I see that you already have this listed in your smb.conf.

Taking a skim through the callers it seems that delete_and_reload_printers() may be invoked via the NetShareEnum code path... Could you please attach "log level = 10" logs in the lead up to these messages so that we can confirm this?
Comment 3 Nate Stuyvesant 2021-11-08 03:24:26 UTC
Odd situation... I changed log level to 10 and restarted smbd then logged back into the server. Now, I cannot see any logging of this problem.

If I change log level to 9 and do the same thing, the error is there.

Here are 10 lines before and after the issue with log level 9...

[2021/11/07 22:21:41.740655,  4] ../../source3/smbd/sec_ctx.c:319(set_sec_ctx_internal)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2021/11/07 22:21:41.740705,  5] ../../libcli/security/security_token.c:52(security_token_debug)
  Security token: (NULL)
[2021/11/07 22:21:41.740754,  5] ../../source3/auth/token_util.c:873(debug_unix_user_token)
  UNIX token of user 0
  Primary group is 0 and contains 0 supplementary groups
[2021/11/07 22:21:41.741061,  1] ../../source3/printing/printer_list.c:234(printer_list_get_last_refresh)
  Failed to fetch record!
[2021/11/07 22:21:41.741141,  1] ../../source3/smbd/server_reload.c:66(delete_and_reload_printers)
  pcap cache not loaded
[2021/11/07 22:21:41.741300,  8] ../../source3/param/service.c:55(load_registry_shares)
  load_registry_shares()
[2021/11/07 22:21:41.741379,  4] ../../source3/smbd/sec_ctx.c:437(pop_sec_ctx)
  pop_sec_ctx (1000, 100) - sec_ctx_stack_ndx = 1
[2021/11/07 22:21:41.741479,  5] ../../source3/rpc_server/srvsvc/srv_srvsvc_nt.c:1628(_srvsvc_NetShareEnumAll)
  _srvsvc_NetShareEnumAll: 1628
[2021/11/07 22:21:41.741572,  4] ../../source3/smbd/sec_ctx.c:437(pop_sec_ctx)
  pop_sec_ctx (1000, 100) - sec_ctx_stack_ndx = 0
[2021/11/07 22:21:41.746160,  5] ../../source3/smbd/uid.c:326(change_to_user_impersonate)
  change_to_user_impersonate: Skipping user change - already user
Comment 4 David Disseldorp 2021-11-08 09:32:29 UTC
(In reply to Nate Stuyvesant from comment #3)
> Odd situation... I changed log level to 10 and restarted smbd then logged
> back into the server. Now, I cannot see any logging of this problem.
> 
> If I change log level to 9 and do the same thing, the error is there.
> 
> Here are 10 lines before and after the issue with log level 9...

It's dependent on client traffic, so that just suggests that the client didn't send the enumeration request while level 10 was configured.
Anyhow, this confirms that we are indeed seeing the delete_and_reload_printers() invocation via NetShareEnum:

> ../../source3/rpc_server/srvsvc/srv_srvsvc_nt.c:1628(_srvsvc_NetShareEnumAll)
>   _srvsvc_NetShareEnumAll: 1628
> [2021/11/07 22:21:41.741572,  4]
> ../../source3/smbd/sec_ctx.c:437(pop_sec_ctx)
>   pop_sec_ctx (1000, 100) - sec_ctx_stack_ndx = 0
> [2021/11/07 22:21:41.746160,  5]
> ../../source3/smbd/uid.c:326(change_to_user_impersonate)
>   change_to_user_impersonate: Skipping user change - already user

Patch to follow...
Comment 5 David Disseldorp 2021-11-08 11:56:48 UTC
Created attachment 16967 [details]
proposed fix

Andreas: please push if you're okay with the proposed fix.
Comment 6 Samba QA Contact 2021-11-08 13:28:03 UTC
This bug was referenced in samba master:

f4cad8b2bc34ecf535deab8979a6e5f6b22233ff
Comment 7 Nate Stuyvesant 2021-11-08 16:10:24 UTC
What's odd is that I performed the same steps with a single macOS client using log levels 9 and 10 (switching between then several times to see if it was an aberration).

The "pcap cache not loaded" error is very easy to reproduce within seconds of use (except with log level 10).

Wonder if there's some issue with log level 10 as well?

Thanks for working on a fix.

If you Google "pcap cache not loaded", you'll see lots of others running into this. Some needed to change their smb.con but others were running into the same issue I was after having all the right configuration settings to disable printing.
Comment 8 David Disseldorp 2021-11-08 18:54:04 UTC
(In reply to Nate Stuyvesant from comment #7)
> What's odd is that I performed the same steps with a single macOS client
> using log levels 9 and 10 (switching between then several times to see if it
> was an aberration).
> 
> The "pcap cache not loaded" error is very easy to reproduce within seconds
> of use (except with log level 10).
> 
> Wonder if there's some issue with log level 10 as well?

Any log messages visible at level 9 should also be visible at level 10, so my guess is that it's some client caching behaviour which sees it avoid share enumeration under certain conditions.

> Thanks for working on a fix.
> 
> If you Google "pcap cache not loaded", you'll see lots of others running
> into this. Some needed to change their smb.con but others were running into
> the same issue I was after having all the right configuration settings to
> disable printing.

Thanks for the feedback. If you feel up to compiling your own Samba, then please give the attached patch a run in your environment. If not, it's now in the master branch, so should make it into a future release.
Comment 9 Nate Stuyvesant 2021-11-10 04:40:40 UTC
Will try to install from the latest. Have not had a chance to do this before.

Got all the dependencies installed except libtracker-sparql-2.0-dev.
As I'm using Ubuntu 21.10, it was replaced by libtracker-sparql-3.0-dev and the old one is not accessible (and Samba wants the old one).

Guess I'll also have to play with the parameters passed to configure a bit.

Might take me a little trial and error.
Comment 10 Nate Stuyvesant 2021-11-10 18:35:36 UTC
Got the latest running on Ubuntu 21.10 with macOS Monterey client and am not seeing the warnings any longer.

Thanks for the help!