SMB problems after upgrading to ElectricEel

malder · December 21, 2024, 5:25pm

SMB was working flawlessly/reliably before upgrading from DragonFish to ElectricEel. On reboot SMB works for a period of time and then is unreachable from my PC’s and VM node. If I go into the System>Services menu and stop SMB, then restart it will not start. I get the following:

 Error: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 211, in call_method
    result = await self.middleware.call_with_audit(message['method'], serviceobj, methodobj, params, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1529, in call_with_audit
    result = await self._call(method, serviceobj, methodobj, params, app=app,
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1460, in _call
    return await methodobj(*prepared_call.args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/schema/processor.py", line 179, in nf
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/schema/processor.py", line 49, in nf
    res = await f(*args, **kwargs)
          ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/plugins/service.py", line 208, in start
    raise CallError(await service_object.failure_logs() or 'Service not running after start')
middlewared.service_exception.CallError: [EFAULT] Dec 21 17:17:07 systemd[1]: Starting smbd.service - Samba SMB Daemon...
Dec 21 17:17:07 systemd[1]: smbd.service: Main process exited, code=exited, status=1/FAILURE
Dec 21 17:17:07 systemd[1]: smbd.service: Failed with result 'exit-code'.
Dec 21 17:17:07 systemd[1]: Failed to start smbd.service - Samba SMB Daemon.

Rebooting TrueNAS and SMB works for a few hours. I’ve searched the forums here and used all the googl-foo I know and have not come up with any fix. Can you point me in the right direction?

Captain_Morgan · December 21, 2024, 11:43pm

Lets start with hardware description and then any relevant configs … especially SMB.

Its not a common problem… likely something unique to your system.

NickF1227 · December 22, 2024, 12:00am

There may be additional logs in /var/log/samba4/log.smbd to give us some more clues on what is happening.

malder · December 24, 2024, 4:37am

This issue cropped up in conjunction with my dashboard (netdata?) being mostly blank. Could it be related? Netdata log repeats:

2024-12-23 20:24:57: netdata INFO  : MAIN : NETDATA_INSTANCE_CLOUD_INSTANCE_TYPE=unknown
2024-12-23 20:24:57: netdata INFO  : MAIN : NETDATA_INSTANCE_CLOUD_INSTANCE_REGION=unknown
2024-12-23 20:24:57: netdata ERROR : MAIN : Failed to initialize database at /var/db/system/netdata/netdata-meta.db, due to "disk I/O error"
2024-12-23 20:24:57: netdata FATAL : netdata : Failed to initialize SQLite # : Success

/usr/sbin/netdata(+0x57893)[0x5604ef57e893]
/usr/sbin/netdata(+0xbb289)[0x5604ef5e2289]
/usr/sbin/netdata(+0x16628)[0x5604ef53d628]
/lib/x86_64-linux-gnu/libc.so.6(+0x2724a)[0x7fef5a77824a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85)[0x7fef5a778305]
/usr/sbin/netdata(+0x176a1)[0x5604ef53e6a1]
2024-12-23 20:24:57: netdata INFO  : MAIN : EXIT: netdata prepares to exit with code 1...
2024-12-23 20:24:57: netdata INFO  : MAIN : EXIT: cleaning up the database...
2024-12-23 20:24:57: netdata INFO  : MAIN : Cleaning up database [0 hosts(s)]...
2024-12-23 20:24:57: netdata INFO  : MAIN : EXIT: all done - netdata is now exiting - bye bye...
EOF found in spawn pipe.
Shutting down spawn server event loop.

I am currently running ElectricEel-24.10.1 on bare metal. Nothing particularly interesting:
Data Topology: 1 x RAIDZ2 | 6 wide | 10.91 TiB
CPU: i5-9600T
MB: Supermicro x11sca-f
RAM: 64GB DDR4
Boot drive: 1TB M.2

I’ve attempted to run the ‘debug’ and failed with the following error:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/middlewared/job.py", line 509, in run
    await self.future
  File "/usr/lib/python3/dist-packages/middlewared/job.py", line 556, in __run_body
    rv = await self.middleware.run_in_thread(self.method, *args)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1367, in run_in_thread
    return await self.run_in_executor(io_thread_pool_executor, method, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/main.py", line 1364, in run_in_executor
    return await loop.run_in_executor(pool, functools.partial(method, *args, **kwargs))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/schema/processor.py", line 183, in nf
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/schema/processor.py", line 55, in nf
    res = f(*args, **kwargs)
          ^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/middlewared/plugins/system/debug.py", line 109, in debug
    raise CallError(debug_job.error)
middlewared.service_exception.CallError: [EFAULT] [EFAULT] Failed to generate debug: OSError(5, 'Input/output error')

I then decided to reboot and attempt to run debug again and it was successful.

/var/log/samba4/log.smbd appears to be repeating the following every 10 seconds

[2024/12/23 19:49:00.344964,  1] ../../lib/messaging/messages_dgm.c:1073(messaging_dgm_init)
  messaging_dgm_init: bind failed: Input/output error
[2024/12/23 19:49:00.345245,  0] ../../source3/lib/util.c:487(reinit_after_fork)
  messaging_reinit() failed: NT_STATUS_IO_DEVICE_ERROR
[2024/12/23 19:49:00.345433,  0] ../../source3/smbd/server.c:1024(smbd_accept_connection)
  reinit_after_fork() failed
[2024/12/23 19:49:00.345501,  0] ../../lib/util/fault.c:178(smb_panic_log)
  ===============================================================
[2024/12/23 19:49:00.345557,  0] ../../lib/util/fault.c:179(smb_panic_log)
  INTERNAL ERROR: reinit_after_fork() failed in smbd () () pid 4159332 (4.20.5-truenas)
[2024/12/23 19:49:00.345612,  0] ../../lib/util/fault.c:186(smb_panic_log)
  If you are running a recent Samba version, and if you think this problem is not yet fixed in the latest versions, please consider reporting this bug, see https://wiki.samba.org/index.php/Bug_Reporting
[2024/12/23 19:49:00.345660,  0] ../../lib/util/fault.c:191(smb_panic_log)
  ===============================================================
[2024/12/23 19:49:00.345706,  0] ../../lib/util/fault.c:192(smb_panic_log)
  PANIC (pid 4159332): reinit_after_fork() failed in 4.20.5-truenas
[2024/12/23 19:49:00.347470,  0] ../../lib/util/fault.c:303(log_stack_trace)
  BACKTRACE: 13 stack frames:
   #0 /usr/lib/x86_64-linux-gnu/samba/libgenrand-private-samba.so(log_stack_trace+0x2e) [0x7fcd28ed65be]
   #1 /usr/lib/x86_64-linux-gnu/samba/libgenrand-private-samba.so(smb_panic+0x9) [0x7fcd28ed6859]
   #2 /usr/sbin/smbd(+0x9e6b) [0x55de509f7e6b]
   #3 /lib/x86_64-linux-gnu/libtevent.so.0(tevent_common_invoke_fd_handler+0x91) [0x7fcd29051781]
   #4 /lib/x86_64-linux-gnu/libtevent.so.0(+0xfac9) [0x7fcd29058ac9]
   #5 /lib/x86_64-linux-gnu/libtevent.so.0(+0xd137) [0x7fcd29056137]
   #6 /lib/x86_64-linux-gnu/libtevent.so.0(_tevent_loop_once+0x91) [0x7fcd29050911]
   #7 /lib/x86_64-linux-gnu/libtevent.so.0(tevent_common_loop_wait+0x1b) [0x7fcd29050c0b]
   #8 /lib/x86_64-linux-gnu/libtevent.so.0(+0xd0d7) [0x7fcd290560d7]
   #9 /usr/sbin/smbd(main+0x1391) [0x55de509f51a1]
   #10 /lib/x86_64-linux-gnu/libc.so.6(+0x2724a) [0x7fcd28cc924a]
   #11 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7fcd28cc9305]
   #12 /usr/sbin/smbd(_start+0x21) [0x55de509f5ab1]
[2024/12/23 19:49:00.347919,  0] ../../source3/lib/dumpcore.c:317(dump_core)
  coredump is handled by helper binary specified at /proc/sys/kernel/core_pattern
[2024/12/23 19:49:10.931099,  1] ../../lib/messaging/messages_dgm.c:1073(messaging_dgm_init)
  messaging_dgm_init: bind failed: Input/output error
[2024/12/23 19:49:10.931392,  0] ../../source3/lib/util.c:487(reinit_after_fork)
  messaging_reinit() failed: NT_STATUS_IO_DEVICE_ERROR
[2024/12/23 19:49:10.931580,  0] ../../source3/smbd/server.c:1024(smbd_accept_connection)
  reinit_after_fork() failed
[2024/12/23 19:49:10.931646,  0] ../../lib/util/fault.c:178(smb_panic_log)
  ===============================================================
[2024/12/23 19:49:10.931703,  0] ../../lib/util/fault.c:179(smb_panic_log)
  INTERNAL ERROR: reinit_after_fork() failed in smbd () () pid 4160267 (4.20.5-truenas)
[2024/12/23 19:49:10.931758,  0] ../../lib/util/fault.c:186(smb_panic_log)
  If you are running a recent Samba version, and if you think this problem is not yet fixed in the latest versions, please consider reporting this bug, see https://wiki.samba.org/index.php/Bug_Reporting
[2024/12/23 19:49:10.931807,  0] ../../lib/util/fault.c:191(smb_panic_log)
  ===============================================================
[2024/12/23 19:49:10.931852,  0] ../../lib/util/fault.c:192(smb_panic_log)
  PANIC (pid 4160267): reinit_after_fork() failed in 4.20.5-truenas
[2024/12/23 19:49:10.933645,  0] ../../lib/util/fault.c:303(log_stack_trace)
  BACKTRACE: 13 stack frames:
   #0 /usr/lib/x86_64-linux-gnu/samba/libgenrand-private-samba.so(log_stack_trace+0x2e) [0x7fcd28ed65be]
   #1 /usr/lib/x86_64-linux-gnu/samba/libgenrand-private-samba.so(smb_panic+0x9) [0x7fcd28ed6859]
   #2 /usr/sbin/smbd(+0x9e6b) [0x55de509f7e6b]
   #3 /lib/x86_64-linux-gnu/libtevent.so.0(tevent_common_invoke_fd_handler+0x91) [0x7fcd29051781]
   #4 /lib/x86_64-linux-gnu/libtevent.so.0(+0xfac9) [0x7fcd29058ac9]
   #5 /lib/x86_64-linux-gnu/libtevent.so.0(+0xd137) [0x7fcd29056137]
   #6 /lib/x86_64-linux-gnu/libtevent.so.0(_tevent_loop_once+0x91) [0x7fcd29050911]
   #7 /lib/x86_64-linux-gnu/libtevent.so.0(tevent_common_loop_wait+0x1b) [0x7fcd29050c0b]
   #8 /lib/x86_64-linux-gnu/libtevent.so.0(+0xd0d7) [0x7fcd290560d7]
   #9 /usr/sbin/smbd(main+0x1391) [0x55de509f51a1]
   #10 /lib/x86_64-linux-gnu/libc.so.6(+0x2724a) [0x7fcd28cc924a]
   #11 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7fcd28cc9305]
   #12 /usr/sbin/smbd(_start+0x21) [0x55de509f5ab1]
[2024/12/23 19:49:10.934101,  0] ../../source3/lib/dumpcore.c:317(dump_core)
  coredump is handled by helper binary specified at /proc/sys/kernel/core_pattern

NickF1227 · December 24, 2024, 4:43am

All of the logs you posted seem to indicate a potentially significant hardware issue causing I/O issues.

You might want to run a SMART test on your drives to dig in and prepare to replace any that fail.

malder · December 24, 2024, 4:54am

I am sorry for my ignorance here - I set up SMART tests to run on a schedule and I’ve seen alerts come up on the little GUI bell. I can’t see anywhere to get more information on the alerts though. They read like this:

Critical
Device: /dev/sda [SAT], ATA error count increased from 2 to 8.
2024-12-21 12:18:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], failed to read SMART Attribute Data.
2024-12-21 12:48:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], Read SMART Self-Test Log Failed.
2024-12-21 12:48:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sdc [SAT], 96 Currently unreadable (pending) sectors.
2024-12-21 15:18:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sdc [SAT], 96 Offline uncorrectable sectors.
2024-12-21 15:18:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], not capable of SMART self-check.
2024-12-21 17:48:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], Read SMART Error Log Failed.
2024-12-21 17:48:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sdc [SAT], Self-Test Log error count increased from 7 to 8.
2024-12-22 04:48:10 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], 40 Currently unreadable (pending) sectors.
2024-12-23 20:24:34 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], 40 Offline uncorrectable sectors.
2024-12-23 20:24:34 (America/Los_Angeles)
Dismiss
cancel
Critical
Device: /dev/sda [SAT], ATA error count increased from 8 to 14.
2024-12-23 20:24:34 (America/Los_Angeles)
Dismiss

I also have a FAILED in the SMART test results page, but no further information. I have an email drafted to the vendor I bought the drives from to inquire about the failed tests.

Is there more information to be had or is that it? Should I be replacing these two drives?

NickF1227 · December 24, 2024, 5:02am

You can run smartctl -a /dev/sda from the command line if you want, this will give you more info. but the information in the alert mean you should probably immediately replace those drives it is alerting you about.

malder · December 24, 2024, 5:07am

Thanks for all your help. I’m going to replace the drives (hopefully under warranty) and hope that clears all of this up.

malder · December 31, 2024, 3:40am

This is the smartctl of one of the drives I am having issues with. Why would it be failing the test with a read error, but also have “No Errors Logged”?

=== START OF INFORMATION SECTION ===
Device Model:     ST12000NM0127
Serial Number:    ZJV5QVKN
LU WWN Device Id: 5 000c50 0c29dfc9b
Firmware Version: G005
User Capacity:    12,000,138,625,024 bytes [12.0 TB]
Sector Sizes:     512 bytes logical, 4096 bytes physical
Rotation Rate:    7200 rpm
Form Factor:      3.5 inches
Device is:        Not in smartctl database 7.3/5625
ATA Version is:   ACS-3 T13/2161-D revision 5
SATA Version is:  SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is:    Mon Dec 30 19:36:46 2024 PST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled

=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

General SMART Values:
Offline data collection status:  (0x82) Offline data collection activity
                                        was completed without error.
                                        Auto Offline Data Collection: Enabled.
Self-test execution status:      ( 121) The previous self-test completed having
                                        the read element of the test failed.
Total time to complete Offline 
data collection:                (  567) seconds.
Offline data collection
capabilities:                    (0x7b) SMART execute Offline immediate.
                                        Auto Offline data collection on/off support.
                                        Suspend Offline collection upon new
                                        command.
                                        Offline surface scan supported.
                                        Self-test supported.
                                        Conveyance Self-test supported.
                                        Selective Self-test supported.
SMART capabilities:            (0x0003) Saves SMART data before entering
                                        power-saving mode.
                                        Supports SMART auto save timer.
Error logging capability:        (0x01) Error logging supported.
                                        General Purpose Logging supported.
Short self-test routine 
recommended polling time:        (   1) minutes.
Extended self-test routine
recommended polling time:        (1111) minutes.
Conveyance self-test routine
recommended polling time:        (   2) minutes.
SCT capabilities:              (0x50bd) SCT Status supported.
                                        SCT Error Recovery Control supported.
                                        SCT Feature Control supported.
                                        SCT Data Table supported.

SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME          FLAG     VALUE WORST THRESH TYPE      UPDATED  WHEN_FAILED RAW_VALUE
  1 Raw_Read_Error_Rate     0x000f   076   064   044    Pre-fail  Always       -       37126504
  3 Spin_Up_Time            0x0003   090   090   000    Pre-fail  Always       -       0
  4 Start_Stop_Count        0x0032   100   100   020    Old_age   Always       -       141
  5 Reallocated_Sector_Ct   0x0033   100   100   010    Pre-fail  Always       -       0
  7 Seek_Error_Rate         0x000f   087   060   045    Pre-fail  Always       -       516907597
  9 Power_On_Hours          0x0032   077   077   000    Old_age   Always       -       20628
 10 Spin_Retry_Count        0x0013   100   100   097    Pre-fail  Always       -       0
 12 Power_Cycle_Count       0x0032   100   100   020    Old_age   Always       -       40
184 End-to-End_Error        0x0032   100   100   099    Old_age   Always       -       0
187 Reported_Uncorrect      0x0032   100   100   000    Old_age   Always       -       0
188 Command_Timeout         0x0032   100   099   000    Old_age   Always       -       4295032833
190 Airflow_Temperature_Cel 0x0022   084   047   040    Old_age   Always       -       16 (Min/Max 10/24)
192 Power-Off_Retract_Count 0x0032   100   100   000    Old_age   Always       -       236
193 Load_Cycle_Count        0x0032   100   100   000    Old_age   Always       -       979
194 Temperature_Celsius     0x0022   016   053   000    Old_age   Always       -       16 (0 9 0 0 0)
195 Hardware_ECC_Recovered  0x001a   012   002   000    Old_age   Always       -       37126504
197 Current_Pending_Sector  0x0012   100   100   000    Old_age   Always       -       96
198 Offline_Uncorrectable   0x0010   100   100   000    Old_age   Offline      -       96
199 UDMA_CRC_Error_Count    0x003e   200   200   000    Old_age   Always       -       1
200 Multi_Zone_Error_Rate   0x0023   100   100   001    Pre-fail  Always       -       0
240 Head_Flying_Hours       0x0000   100   253   000    Old_age   Offline      -       20513 (11 193 0)
241 Total_LBAs_Written      0x0000   100   253   000    Old_age   Offline      -       1710564087208
242 Total_LBAs_Read         0x0000   100   253   000    Old_age   Offline      -       1900580624357

SMART Error Log Version: 1
No Errors Logged

SMART Self-test log structure revision number 1
Num  Test_Description    Status                  Remaining  LifeTime(hours)  LBA_of_first_error
# 1  Extended offline    Completed: read failure       90%     20530         371116944
# 2  Short offline       Completed without error       00%     20516         -
# 3  Extended offline    Completed: read failure       90%     20421         371116944
# 4  Short offline       Completed without error       00%     20348         -
# 5  Short offline       Completed without error       00%     20180         -
# 6  Extended offline    Completed: read failure       90%     20085         371116944
# 7  Short offline       Completed without error       00%     20012         -
# 8  Short offline       Completed without error       00%     19796         -
# 9  Extended offline    Completed: read failure       90%     19701         371116944
#10  Short offline       Completed without error       00%     19629         -
#11  Short offline       Completed without error       00%     19461         -
#12  Extended offline    Completed: read failure       90%     19374         371116944
#13  Short offline       Completed without error       00%     19301         -
#14  Short offline       Completed without error       00%     19060         -
#15  Extended offline    Completed: read failure       90%     18965         371116944
#16  Short offline       Completed without error       00%     18892         -
#17  Short offline       Completed without error       00%     18724         -
#18  Extended offline    Completed: read failure       90%     18629         371116944
#19  Short offline       Completed without error       00%     18556         -
#20  Short offline       Completed without error       00%     18340         -
#21  Extended offline    Completed: read failure       90%     18245         371116944

SMART Selective self-test log data structure revision number 1
 SPAN  MIN_LBA  MAX_LBA  CURRENT_TEST_STATUS
    1        0        0  Not_testing
    2        0        0  Not_testing
    3        0        0  Not_testing
    4        0        0  Not_testing
    5        0        0  Not_testing
Selective self-test flags (0x0):

NickF1227 · December 31, 2024, 2:26pm

Reading SMART data is a pain.

197 Current_Pending_Sector  0x0012   100   100   000    Old_age   Always       -       96
198 Offline_Uncorrectable   0x0010   100   100   000    Old_age   Offline      -       96
199 UDMA_CRC_Error_Count    0x003e   200   200   000    Old_age   Always       -       1

You have 96 Current_Pending_Sector/Offline_Uncorrectable and 1 UDMA_CRC_Error_Count

It also has failed several extended tests

# 1  Extended offline    Completed: read failure       90%     20530         371116944