Improved logging in Samba Winbind
Keeping Track
The Winbind service offers various services for the name service switch (NSS) and pluggable authentication modules (PAMs). On the Windows side, Winbind communicates with the Local Security Authority (LSA), Netlogon, and Lightweight Directory Access Protocol (LDAP) services of a domain controller to localize user accounts, read user data, and ultimately authenticate users. You can use Samba's own net tool, but also Realm [1], as the front end for joining a client to a domain. With Realm, you need to specify the --client-software=winbind
option to ensure that the Winbind service and not the system security services daemon (SSSD) is used to join a domain.
Cluttered Logfiles
The primary Winbind process creates a separate child process for each logical AD domain that the service wants to access. Each process is also assigned its own logfile, where you will find varying amounts of information depending on the configured logging level. If you experience issues with integration into a Windows environment, you should set the logging level to a high value to glean as much information as possible for debugging.
The problem in this case is that the sheer volume of log data makes it difficult to understand communication between the Winbind process and a domain controller. The individual entries each comprise a header and the message. Besides a timestamp, the header also contains various other details, such as the configured logging level, Winbind's process ID, the log message class, and the Winbind function that was used, as shown in the following example of a log message from the nss_winbind library:
[2023/05/04 16:20:51.998105, 3, pid=1153814, effective(0, 0), real(0, 0), class=winbind] ../../source3/winbindd/winbindd.c:502(process_request_send) process_request_send: [nss_winbind (1153856)] Handling async request: GETPWNAM
Because Winbind performs asynchronous function calls, the logfiles are difficult to read. The log message examples in Figure 1 illustrate this problem. The first entry belongs to a query for the user named JOE
from AD domain ADDOMAIN
, with the aim of discovering the user's security identifier (SID). The next message then outputs a SID. However, if you then use the wbinfo
tool to validate the data, you will see that Joe has a SID ending in 1110 and the SID ending in 1107 belongs to Alice:
$ wbinfo --name-to-sid ADDOMAIN/joe S-1-5-21-118052468-2300894008-1344842092-1110 SID_USER (1) $ wbinfo --name-to-sid ADDOMAIN/alice S-1-5-21-118052468-2300894008-1344842092-1107 SID_USER (1)
The problem now is simply that you cannot establish a relationship between the individual log messages because of the asynchronous function calls, which is precisely the problem the developers solved in Samba 4.17.
Winbind Tracing
To solve this relationship problem, the headers of the individual log messages have been extended to include a traceid
field. In Figure 1, you can see this field and that the values for the field differ between the two messages. In the first case, the trace ID is 92, but in the second case it is 90. This output makes it immediately clear that the messages belong to different queries. If you are looking for the entries that belong to a specific query, you can now simply use a new tool, which has been around since Samba 4.19, to find the trace ID of log messages.
Besides traceid
, another new field, depth
, lets you easily identify the nesting level of an individual request. This information is quite helpful, because a single query can generate many different sub-requests. The depth ID helps you identify the relationship between individual messages and the order in which the individual functions were called.
To identify the nesting level visually, Winbind even indents the sub-requests that belong to a trace ID by four spaces in each case. Thanks to this new type of Winbind log tracing, it is now very easy to identify the individual function calls that belong to a query so that you can clearly trace the communication paths.
Configuration and New Tool
To make sure Winbind uses these two new header fields in the log messages, you need to set a new option in the /etc/samba/smb.conf
configuration file:
# winbind debug traceid = yes
To view all log messages that belong to a specific trace ID, simply use the new samba-log-parser
tool:
# samba-log-parser --traceid 92 /var/log/samba/
The beauty of the tool is that, to see all the messages of a trace ID and the file from which the messages originate, you only need to specify the ID and the log directory (Figure 2) – regardless of the logfile in which the message is stored. You can also use timestamps to sort the existing logs for a specific trace ID and generate a new logfile. As in the last example, samba-log-parser
then shows the file from which the individual messages originate:
# samba-log-parser --traceid 82 --merge-by-timestamp /var/log/samba > traces-82-by-timestamp.log
This option is helpful because you now have a chronological sequence of all messages for the specified trace ID in the traces-82-by-timestamp.log
file. Finally, the tool also shows a flow tracing, which means you only get to see the functions, without any details, that a particular request uses. This output can be helpful for complex queries to establish the functions that are called without having to read the log messages. The samba-log-parser
command then looks like:
# samba-log-parser --traceid 81 --flow /var/log/samba
Whereas the traceid
and depth
header fields are available regardless of the defined logging level, flow traces require a logging level of 20. You can easily set this by typing the
# smbcontrol all debug 20
command.
Buy this article as PDF
(incl. VAT)