On 03 November 2022 19:59, Tim ODriscoll via samba wrote:>On 03 November 2022 16:44, Jeremy Allison via samba wrote: >> Can you do an strace on an rpcd_winreg process ? That seems an inordinate >> amount of CPU... > >There's no printing activity on the server at the moment, but there are still a few lingering rpcd_winreg processes, so I picked the longest running one and ran >'strace -p 18841 -o rpcd_winreg.strace', left it running for 5 seconds and [ctrl]+c to stop it. >I'm beginning to suspect this is communication issue between Windows and Samba: On my brand new print server, I've only tried setting up one client (Windows 11), yet the server is still showing one rpcd_winreg process taking up 100% CPU and it's been running since the sernet-samba-ad service was last started. Looking through the rpcd_spoolss log file, every few seconds there is an authentication request from the Windows client's logged in user, then a request for the printer list. The Windows client is apparently idle, I should point out. So, I'm now wondering if there's a GPO I've made recently which has a setting that is making Windows expect a certain response from a print server that Samba isn't giving it. Tim Here's a snippet from the log file - all these entries are for the logged in user on my test machine, on which I've added a printer from the new DC: grep authentication_event /var/log/samba/log.rpcd_spoolss [2022/11/04 09:20:46, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:47, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:47, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:48, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:53, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:53, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:56, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:56, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:57, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:57, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:58, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:58, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:20:59, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:04, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:06, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:06, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:07, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:07, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:08, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:09, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:09, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:15, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:16, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:16, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:17, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:17, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:18, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:20, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:20, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:26, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:26, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:27, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:27, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:27, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:28, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:30, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:32, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:36, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:36, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:37, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:37, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:38, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:40, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable)
Achim Gottinger
2023-Sep-29 09:01 UTC
[Samba] 4.17.1 rpcd_winreg, rpcd_spoolss and printing
Am 04.11.2022 um 10:38 schrieb Tim ODriscoll via samba:> On 03 November 2022 19:59, Tim ODriscoll via samba wrote: >> On 03 November 2022 16:44, Jeremy Allison via samba wrote: >>> Can you do an strace on an rpcd_winreg process ? That seems an inordinate >>> amount of CPU... >> There's no printing activity on the server at the moment, but there are still a few lingering rpcd_winreg processes, so I picked the longest running one and ran >'strace -p 18841 -o rpcd_winreg.strace', left it running for 5 seconds and [ctrl]+c to stop it. >> > I'm beginning to suspect this is communication issue between Windows and Samba: > On my brand new print server, I've only tried setting up one client (Windows 11), yet the server is still showing one rpcd_winreg process taking up 100% CPU and it's been running since the sernet-samba-ad service was last started. > > Looking through the rpcd_spoolss log file, every few seconds there is an authentication request from the Windows client's logged in user, then a request for the printer list. The Windows client is apparently idle, I should point out. > > So, I'm now wondering if there's a GPO I've made recently which has a setting that is making Windows expect a certain response from a print server that Samba isn't giving it. > > Tim > > Here's a snippet from the log file - all these entries are for the logged in user on my test machine, on which I've added a printer from the new DC: > grep authentication_event /var/log/samba/log.rpcd_spoolss > [2022/11/04 09:20:46, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:47, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:47, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:48, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:53, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:53, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:56, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:56, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:57, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:57, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:58, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:58, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:20:59, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:04, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:06, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:06, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:07, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:07, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:08, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:09, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:09, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:15, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:16, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:16, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:17, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:17, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:18, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:20, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:20, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:26, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:26, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:27, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:27, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:27, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:28, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:30, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:32, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:36, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:36, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:37, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:37, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:38, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:40, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) > [2022/11/04 09:21:41, 3] ../../auth/auth_log.c:647(log_authentication_event_human_readable) >Hello Tim, I'm having a similar issue. After updating from Debian Wheezy with Samba 4.7.7 to bookworm with samba 4.18.6. On at least two locations printing takes up to 10 minutes and i see alot of rpcd_winreg, rpcd_spoolss processes consuming alot of memory. I can temporary fix it by restarting samba. How did you fix it on your side? Thanks in advance, Achim