11.3 U2.1. Time Machine share crashes smbd

[Mark Levitt]

Hi,

I've spent the morning trying to figure out what's happening and I'm stuck.

I've been using freenas as a time machine backup server since 11.0. It was working fine definitely in 11.1 and 11.2. Sometime after upgrading to 11.3, time machine backups seem to have been silently failing so I started investigating.

I noticed that normal shares seem to work fine, but whenever I start a time machine backup, smbd panics gets relaunched repeatedly:

Code:

Apr 26 13:00:42 FreeNAS kernel: pid 56914 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:42 FreeNAS kernel: pid 56915 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:42 FreeNAS kernel: pid 56916 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:43 FreeNAS kernel: pid 56917 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:43 FreeNAS kernel: pid 56918 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:43 FreeNAS kernel: pid 56919 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:43 FreeNAS kernel: pid 56920 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)
Apr 26 13:00:43 FreeNAS kernel: pid 56921 (smbd), jid 0, uid 0: exited on signal 6 (core dumped)

I have tried creating a new dataset for the time machine disk and creating a new time machine share (with the Time Machine option set).

What I have noticed is that, when I first create the share and start a backup, time machine seems to connect, starts creating the time machine sparse bundle, and then stops almost immediately. The logs on the macOS side read:

Code:

2020-04-26 12:49:52.036608+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Starting manual backup
2020-04-26 12:49:52.244757+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Attempting to mount 'smb://mlevitt@freenas._smb._tcp.local/TMBackup'
2020-04-26 12:49:52.626271+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Mounted 'smb://mlevitt@freenas._smb._tcp.local/TMBackup' at '/Volumes/com.apple.TimeMachine.TMBackup-778246AE-925B-4897-BBC7-7E9F1CAF9D5F'
2020-04-26 12:49:53.244630+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Failed to find matching sparsebundle in directory '/Volumes/com.apple.TimeMachine.TMBackup-778246AE-925B-4897-BBC7-7E9F1CAF9D5F', directory contents: (
    ".DS_Store"
)
2020-04-26 12:49:53.458458+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Creating a sparsebundle using Case-sensitive Journaled HFS+ filesystem
2020-04-26 12:49:55.594728+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to create '/Volumes/com.apple.TimeMachine.TMBackup-778246AE-925B-4897-BBC7-7E9F1CAF9D5F/E6C66549-8F43-5779-9AEA-461F5906CD92.sparsebundle', results: {
}, error: 5 Input/output error
2020-04-26 12:49:55.595018+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogError] statfs failed for '/Volumes/com.apple.TimeMachine.TMBackup-778246AE-925B-4897-BBC7-7E9F1CAF9D5F', error: 2 No such file or directory
2020-04-26 12:49:55.595088+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogError] '/Volumes/com.apple.TimeMachine.TMBackup-778246AE-925B-4897-BBC7-7E9F1CAF9D5F' is not a valid mount point!
2020-04-26 12:49:55.595154+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Backup failed because the network destination disk was ejected or disconnected unexpectedly!
2020-04-26 12:49:55.596413+0100  localhost backupd[40973]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Backup failed with error 26: The connection to the server was interrupted.

If I manually connect to the TMBackup share from the Finder before I start the Time Machine backup, I can write to the share. However, once the Time Machine backup fails, if I try connecting again, I receive an error from macOS:

"The operation can't be completed. An unexpected error occurred (error code -8058)."

Here is the output of testparm -s:

Code:

root@freenas[~]# testparm -s
Load smb config files from /usr/local/etc/smb4.conf
Loaded services file OK.
Server role: ROLE_STANDALONE

# Global parameters
[global]
    aio max threads = 2
    bind interfaces only = Yes
    disable spoolss = Yes
    dns proxy = No
    enable web service discovery = Yes
    kernel change notify = No
    load printers = No
    logging = file
    map to guest = Bad User
    max log size = 51200
    nsupdate command = /usr/local/bin/samba-nsupdate -g
    obey pam restrictions = Yes
    server min protocol = SMB2_02
    server role = standalone server
    server string = FreeNAS Server
    unix extensions = No
    idmap config *: range = 90000001-100000000
    fruit:nfs_aces = No
    idmap config * : backend = tdb
    allocation roundup size = 0
    directory name cache size = 0
    dos filemode = Yes
    include = /usr/local/etc/smb4_share.conf


[Media]
    aio write size = 0
    ea support = No
    level2 oplocks = No
    mangled names = illegal
    oplocks = No
    path = /mnt/tank/media
    read only = No
    strict locking = Yes
    vfs objects = fruit streams_xattr zfs_space zfsacl
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream
    streams_xattr:store_stream_type = no
    streams_xattr:prefix = user.
    fruit:locking = netatalk


[Recordings]
    aio write size = 0
    ea support = No
    mangled names = illegal
    path = /mnt/tank/mythtv/recordings
    vfs objects = fruit streams_xattr zfs_space zfsacl
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream


[Shared]
    aio write size = 0
    ea support = No
    guest ok = Yes
    mangled names = illegal
    path = /mnt/tank/shared
    read only = No
    vfs objects = fruit streams_xattr ixnas
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream


[Storage]
    aio write size = 0
    ea support = No
    mangled names = illegal
    path = /mnt/tank/storage
    read only = No
    vfs objects = fruit streams_xattr zfs_space zfsacl
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream
    streams_xattr:store_stream_type = no
    streams_xattr:prefix = user.
    fruit:locking = netatalk


[TMBackup]
    aio write size = 0
    ea support = No
    mangled names = illegal
    path = /mnt/tank/TMBackup
    read only = No
    vfs objects = fruit streams_xattr ixnas
    fruit:time machine max size = 2 T
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:volume_uuid = 636e4d36-bc76-4159-96d7-928990b823ce
    fruit:time machine = yes
    fruit:resource = stream
    fruit:metadata = stream


[TestSMBShare]
    aio write size = 0
    ea support = No
    mangled names = illegal
    path = /mnt/tank/TestSMBShare
    read only = No
    vfs objects = fruit streams_xattr shadow_copy_zfs ixnas
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream


[homes]
    aio write size = 0
    browseable = No
    ea support = No
    level2 oplocks = No
    mangled names = illegal
    oplocks = No
    path = /mnt/tank/home/%U
    read only = No
    strict locking = Yes
    vfs objects = fruit streams_xattr zfs_space zfsacl
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream
    streams_xattr:store_stream_type = no
    streams_xattr:prefix = user.
    fruit:locking = netatalk


[iTunes]
    aio write size = 0
    ea support = No
    level2 oplocks = No
    mangled names = illegal
    oplocks = No
    path = /mnt/tank/iTunes
    read only = No
    strict locking = Yes
    vfs objects = fruit streams_xattr zfs_space zfsacl
    nfs4:acedup = merge
    nfs4:chown = true
    fruit:resource = stream
    fruit:metadata = stream
    streams_xattr:store_stream_type = no
    streams_xattr:prefix = user.
    fruit:locking = netatalk
    

ACLs on Time machine dataset:

Code:

root@FreeNAS[/var/log/samba4]# getfacl /mnt/tank/TMBackup
# file: /mnt/tank/TMBackup
# owner: root
# group: family
            owner@:rwxpDdaARWcCos:fd-----:allow
            group@:rwxpDdaARWcCos:fd-----:allow
         everyone@:--------------:fd-----:allow

ACLs on a test dataset (not set as a time machine disk)

Code:

root@FreeNAS[/var/log/samba4]# getfacl /mnt/tank/TestSMBShare
# file: /mnt/tank/TestSMBShare
# owner: root
# group: family
            owner@:rwxpDdaARWcCos:fd-----:allow
            group@:rwxpDdaARWcCos:fd-----:allow
         everyone@:--------------:fd-----:allow

Note: family is a group my user account is a member of.

And pool status:

Code:

root@FreeNAS[/var/log/samba4]# zpool status
  pool: freenas-boot
state: ONLINE
  scan: scrub repaired 0 in 0 days 00:00:40 with 0 errors on Tue Apr 21 03:45:40 2020
config:

        NAME        STATE     READ WRITE CKSUM
        freenas-boot  ONLINE       0     0     0
          ada0p2    ONLINE       0     0     0

errors: No known data errors

  pool: tank
state: ONLINE
  scan: scrub repaired 0 in 0 days 06:38:43 with 0 errors on Sun Mar 29 07:38:45 2020
config:

        NAME                                            STATE     READ WRITE CKSUM
        tank                                            ONLINE       0     0     0
          raidz2-0                                      ONLINE       0     0     0
            gptid/e7800684-5200-11e7-b9b0-d05099c13ab9  ONLINE       0     0     0
            gptid/e82dcb86-5200-11e7-b9b0-d05099c13ab9  ONLINE       0     0     0
            gptid/e8d8b32c-5200-11e7-b9b0-d05099c13ab9  ONLINE       0     0     0
            gptid/e98f2f60-5200-11e7-b9b0-d05099c13ab9  ONLINE       0     0     0
            gptid/ea3f9e66-5200-11e7-b9b0-d05099c13ab9  ONLINE       0     0     0
            gptid/eaf15433-5200-11e7-b9b0-d05099c13ab9  ONLINE       0     0     0

errors: No known data errors

Hardware details are:

Asrock Rack E3C236D4U Intel(R) Xeon(R) CPU E3-1240 v5 @ 3.50GHz 32GB ECC RAM
Built in 1GB Nic
6x4TB WD RED in a raidz2 pool
Boot drive is an M.2 SATA DOM SSD.

Clients are a mix of macOS 10.14.6 and 10.13.6.

Any help would be greatly appreciated.

Thanks!

 

[Mark Levitt]

I think it's related to this bug:

https://jira.ixsystems.com/browse/NAS-105911

 

[anodos]

Can you PM me a debug?

 

[Mark Levitt]

Done.

 

[anodos]

This ended up being a bug in vfs_fruit. It will be fixed in 11.3-U3.

 

[Mark Levitt]

Thanks for your help. Much appreciated.