Bug: error thrown in /usr/local/libexec/truenas_audit_handler.py (25.10.2.1)

TrueNAS General
,
1

In 25.10.2.1 an error is thrown sometimes when a cron job is executed:

timeREDACTED nas CRON\[181341\]: (root) CMD (PATH=“/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin:/root/bin” midclt call cronjob.run 4 true > /dev/null 2> /dev/null)

timeREDACTED nas truenas_audit_handler.py\[178074\]: Traceback (most recent call last):
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 774, in 
timeREDACTED nas truenas_audit_handler.py\[178074\]:     main()
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 770, in main
timeREDACTED nas truenas_audit_handler.py\[178074\]:     loop.run_until_complete(handler.run())
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/lib/python3.11/asyncio/base_events.py”, line 654, in run_until_complete
timeREDACTED nas truenas_audit_handler.py\[178074\]:     return future.result()
timeREDACTED nas truenas_audit_handler.py\[178074\]:            ^^^^^^^^^^^^^^^
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 723, in run
timeREDACTED nas truenas_audit_handler.py\[178074\]:     await self.handle_auditd_msg()
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 709, in handle_auditd_msg
timeREDACTED nas truenas_audit_handler.py\[178074\]:     await self.send_completed(\*completed)
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 671, in send_completed
timeREDACTED nas truenas_audit_handler.py\[178074\]:     json_data = audit_entry_to_json(msgid, data)
timeREDACTED nas truenas_audit_handler.py\[178074\]:                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 589, in audit_entry_to_json
timeREDACTED nas truenas_audit_handler.py\[178074\]:     \__generate_event_data(entry, to_write\[‘TNAUDIT’\])
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 516, in \__generate_event_data
timeREDACTED nas truenas_audit_handler.py\[178074\]:     if (new_event_data := \__parse_raw_msg(item, data_out\[‘event_data’\])) is not None:
timeREDACTED nas truenas_audit_handler.py\[178074\]:                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 490, in \__parse_raw_msg
timeREDACTED nas truenas_audit_handler.py\[178074\]:     return \__parse_pam(msg_type, parts)
timeREDACTED nas truenas_audit_handler.py\[178074\]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
timeREDACTED nas truenas_audit_handler.py\[178074\]:   File “/usr/local/libexec/truenas_audit_handler.py”, line 441, in \__parse_pam
timeREDACTED nas truenas_audit_handler.py\[178074\]:     key, value = item.split(‘=’, 1)
timeREDACTED nas truenas_audit_handler.py\[178074\]:     ^^^^^^^^^^
timeREDACTED nas truenas_audit_handler.py\[178074\]: ValueError: not enough values to unpack (expected 2, got 1)

The audit message that triggers this looks like this (I think the issue is with hostname=Unix socket, it’s treated as 2 values):

type=USER_AUTH msg=audit(REDACTED): pid=1617 uid=0 auid=REDACTED ses=REDACTED subj=unconfined msg='op=PAM:authentication grantors=pam_access acct="root" exe="/usr/bin/python3.11" hostname=UNIX socket (pid=548287 uid=0 gid=0) addr=? terminal=? res=success'UID="root" AUID="unset" UID="root" GID="root"

To silence the error I used this hack:

--- /usr/local/libexec/truenas_audit_handler.broken.py
+++ /usr/local/libexec/truenas_audit_handler.py 
@@ -438,6 +438,8 @@

     # Everything after pam function is variable
     for item in msg_parts[AuditMsgPamBase.FUNCTION.idx + 1:]:
+        if item == "socket":
+            continue
         key, value = item.split('=', 1)

         if value[0] == '"':
2

If you have what you believe to be a bug, use the Report a Bug (smile icon in GUI) or Report a Bug on the top, upper right of the forum. Submit a debug dump also along with all the details.

3

Tried to use that, but when I click on “+ Create” it says I’m not logged in (but I can see the profile and settings links in the top right side). I gave up after 10minutes of trying to create the bug report.

4

Tried to use what, the GUI or the Forum link?

5

The Jira app on https ://ixsystems.atlassian.net/jira/. I haven’t tried from web GUI yet.

6

Sending the bug report from GUI worked (NAS-140373). Thanks.

7

Same issue. This bug was closed, can you create again or just submit a pull request at Github?

8

NAS-140373 was closed because it didn’t have a Debug dump attached. If you can reproduce, open a ticket and make sure to upload a Debug Dump to the ticket.

9

same bug. Has been happening every hour for a couple months. Finally crashed the system today.

opening new ticket - NAS-140897

10

Getting this in a freshly installed 25.10.4 build with practically no configuration changes other than building a pool.

11

Look up the JIRA ticket and see if that is the same issue and/or use Report a Bug to create another ticket if you think your situation is slightly different. Ticket show fix versions for future 26 and 27 versions

NAS-140897

12

Gemini suggested a more broader fix,

def __parse_pam(msg_type: str, msg_parts: list) -> dict:
    event_data = {'event_type': AuditEvent.CREDENTIAL.upper(), 'auth_action': msg_type}

    for item in AuditMsgPamBase:
        key, value = item.get_entry(msg_parts)
        event_data[key] = value

    # Everything after pam function is variable
    for item in msg_parts[AuditMsgPamBase.FUNCTION.idx + 1:]:
        if "=" not in item: continue
        key, value = item.split('=', 1)

        if value[0] == '"':
            value = value[1:]
        if value[-1] == '"':
            value = value[:-1]

        if value.isdigit():
            value = int(value)
        elif value in AUDITD_NULL_VALUES:
            value = None

        match key:
            case 'res':
                value = value.startswith('success')
            case 'AUID':
                key = 'username'
            case 'UID' | 'ID':
                # We're only concerned about logging the audit uid
                continue
            case _:
                pass

        event_data[key] = value

    return event_data

Specifically, the if "=" not in item: continue line. This has quieted the logs quite a bit.

I’m still puzzled how this wasn’t caught/fixed sooner as it happens on a fresh install.

13

Wanted to share a workaround that’s been fully effective for me, and which is more durable than the narrow “skip the word socket” patch suggested earlier in this thread.

Root cause as I’ve now confirmed it: it’s not specific to midclt, and it’s not specific to any one script. ANY job invoked through TrueNAS’s standard /etc/cron.d mechanism (including TrueNAS’s own internal jobs like pool.configure_resilver_priority and update.download) routes through /etc/pam.d/cron’s session-logging chain (common-session-noninteractive, pam_loginuid, etc.), and it’s that PAM session open/close logging that produces the malformed “hostname=UNIX socket (pid=N uid=N gid=N)” audit message which crashes __parse_pam.

Workaround: I had a custom cron job (running every 1 minute) that was crashing tnaudit continuously. I replaced it with a plain systemd timer + oneshot service instead of a cron job:

[Unit]
Description=My custom job
After=zfs.target

[Service]
Type=oneshot
ExecStart=/path/to/my/script.sh
User=root

[Timer]
OnCalendar=*:0/1
AccuracySec=5s
Persistent=true

Since systemd units don’t route through /etc/pam.d/cron at all (no PAMName= directive set), this completely bypasses the trigger. I confirmed zero tnaudit crashes over multiple consecutive 1-minute executions, versus reliable crashes every single minute under the equivalent cron job.

This only addresses jobs I control, of course — TrueNAS’s own internal /etc/cron.d jobs (resilver priority checks, update checks, etc.) still trigger it on their own schedule, just much less frequently (a few times a day rather than continuously), since I can’t modify those.

Why this is better than the narrow string-skip patch already suggested: that patch only handles the one specific “socket” token case observed so far. The systemd-timer approach avoids the PAM session-logging path entirely, so it’s robust against any future malformed PAM message shape, not just this one. It’s also something individual users can apply today without waiting for a patched build, since it requires zero changes to TrueNAS’s own code.