Lead Image © monsit jangariyawong, 123RF.com

Lead Image © monsit jangariyawong, 123RF.com

Improved logging in Samba Winbind

Keeping Track

Article from ADMIN 83/2024
By
In Winbind v4.17, the Samba team has addressed the complexity of and difficulty in troubleshooting the logging service that allows Linux systems to join an Active Directory domain.

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:

Figure 1: Because of Winbind's asynchronous function calls, logfiles cannot be read sequentially.
$ 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
Figure 2: The new samba-log-parser tool shows all messages from different logfiles for a trace ID.

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

Express-Checkout as PDF
Price $2.95
(incl. VAT)

Buy ADMIN Magazine

SINGLE ISSUES
 
SUBSCRIPTIONS
 
TABLET & SMARTPHONE APPS
Get it on Google Play

US / Canada

Get it on Google Play

UK / Australia

Related content

comments powered by Disqus