search

mbentley / docker-timemachine

Docker image to run Samba (compatible Time Machine for macOS)
Apache License 2.0
573 stars 66 forks source link

[Bug/Help]: MacOS Sonoma cannot backup successfully. #158

Closed Piwares closed 8 months ago

Piwares commented 9 months ago

Describe the Bug

I use the mbentley/timemachine:smb to run the time machine backup for MacOS Sonoma on Mac mini 20H1, but it failed with cannot create backup image with "Time Machine error: backup disk image could not be created". The user I used is piwares, and the volume named as timemachine is a lvm type volume created by docker-lvm-plugin. Inside the docker i can create the documents on it, and the timemachine can be mounted by MacOS, and can create file, folder without any problem.

Expected Behavior

Successfully backup the Sonoma

Steps to Reproduce

  1. Add remote disk
  2. Setup disk configuration
  3. Backup is not working.

How You're Launching the Container

docker run -d --restart=unless-stopped \
  --name timemachine \
  --net host \
 -e DEBUG_LEVEL=7 \
  -e CUSTOM_SMB_CONF="false" \
 -e CUSTOM_USER="false" \
  -e HIDE_SHARES="no" \
  -e TM_USERNAME="piwares" \
  -e TM_GROUPNAME="piwares" \
  -e PASSWORD="Piw@res" \
  -e MIMIC_MODEL="TimeCapsule8,119" \
  -e TM_UID="1000" \
  -e TM_GID="1000" \
  -e SET_PERMISSIONS="false" \
  -e VOLUME_SIZE_LIMIT="0" \
  -e SMB_METADATA="stream" \
 -e SMB_VFS_OBJECTS="fruit streams_xattr" \
 -e SMB_INHERIT_PERMISSIONS="true" \
  -v timemachine:/opt/piwares \
  mbentley/timemachine:smb

Container Logs

INFO: Current debug levels:
  all: 7
  tdb: 7
  printdrivers: 7
  lanman: 7
  smb: 7
  rpc_parse: 7
  rpc_srv: 7
  rpc_cli: 7
  passdb: 7
  sam: 7
  auth: 7
  winbind: 7
  vfs: 7
  idmap: 7
  quota: 7
  acls: 7
  locking: 7
  msdfs: 7
  dmapi: 7
  registry: 7
  scavenger: 7
  dns: 7
  ldb: 7
  tevent: 7
  auth_audit: 7
  auth_json_audit: 7
  kerberos: 7
  drs_repl: 7
  smb2: 7
  smb2_credits: 7
  dsdb_audit: 7
  dsdb_json_audit: 7
  dsdb_password_audit: 7
  dsdb_password_json_audit: 7
  dsdb_transaction_audit: 7
  dsdb_transaction_json_audit: 7
  dsdb_group_audit: 7
  dsdb_group_json_audit: 7
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle, access_mask = 0x81, share_access = 0x7 create_options = 0x1, create_disposition = 0x2, file_attributes = 0x10
unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle) inherit mode 42755
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle) returning 042755
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle], expect_close = 0
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle], expect_close = 0
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle/. fname=. (.)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle/.:AFP_AfpInfo] failed
fget_ea_dos_attribute: Cannot get attribute from EA on file 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle/..: Error = No data available
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle/.. fname=.. (..)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle/..:AFP_AfpInfo] failed
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle, access_mask = 0x110080, share_access = 0x0 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
smbd_do_setfilepathinfo: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle (fnum 509446080) info_level=1013 totdata=1
close_directory: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-121045.sparsebundle. Delete on close was set - deleting directory returned NT_STATUS_OK.

Time Machine client Logs

No response

Additional Context

No response

mbentley commented 9 months ago

Could you also provide the startup logs from the entrypoint? They provide additional info for me.

Piwares commented 9 months ago

The startup log is pretty long, so i attached with a file. startup.log

Piwares commented 9 months ago

The version of MacOS is 14.1, and docker version as following: Client: Version: 18.09.0 EulerVersion: 18.09.0.206 API version: 1.39 Go version: go1.15.7 Git commit: Built: Thu Nov 23 01:42:27 2023 OS/Arch: linux/amd64 Experimental: false

Server: Engine: Version: 18.09.0 EulerVersion: 18.09.0.206 API version: 1.39 (minimum version 1.12) Go version: go1.15.7 Git commit: e4c0fb8 Built: Thu Nov 23 01:41:44 2023 OS/Arch: linux/amd64 Experimental: false

mbentley commented 9 months ago

OK, thanks. Looks like it's formatting the filesystem xfs just fine and it is passing the attribute check fine. What about the time machine client logs when you try to run a backup? You can try to trigger a backup and change 6h to something more reasonable like 1h to limit the amount of logs returned:

printf '\e[3J' && log show --predicate 'subsystem == "com.apple.TimeMachine"' --info --last 6h | \
  grep -F 'eMac' | \
  grep -Fv 'etat' | \
  awk -F']' '{print substr($0,1,19), $NF}'

That's a pretty ancient version of Docker there but I would be surprised if that was causing a problem.

You have -e SET_PERMISSIONS="false". Are you manually setting the permissions on the created volume? If not, you can just take the easy route and change that to -e SET_PERMISSIONS="true" \ as that would be a pretty big reason it fails to work.

Piwares commented 9 months ago

Here is the client log of it. it seems the reason of permission, i'll try set_permissions=true and report the result. client.log

Piwares commented 9 months ago

There is no luck for -e SET_PERMISSIONS="true", it give me the same error and same log info for: Code=13 "Permission denied". Mean while, i've recreate the lvm volume of the timemachine storage with docker volume create -d lvm timemachine

The kernel of the host is 4.19.90

mbentley commented 9 months ago

You you re-post the container startup logs? Just the part down to where it says entrypoint complete is good enough, like this:

INFO: CUSTOM_SMB_CONF=false; generating [global] section of /etc/samba/smb.conf...
INFO: Creating /var/log/samba/cores
INFO: Avahi - generating base configuration in /etc/avahi/services/smbd.service...
INFO: Avahi - adding the 'dk0', 'TimeMachine' share txt-record to /etc/avahi/services/smbd.service...
INFO: Group timemachine doesn't exist; creating...
INFO: User timemachine doesn't exist; creating...
INFO: Using default password: timemachine
INFO: chpasswd: password for 'timemachine' changed
INFO: CUSTOM_SMB_CONF=false; generating [TimeMachine] section of /etc/samba/smb.conf...
INFO: Samba - Created Added user timemachine.
INFO: Samba - Enabled user timemachine.
INFO: Samba - setting password
INFO: changed ownership of '/opt/timemachine' to 1000:1000
INFO: mode of '/opt/timemachine' changed to 0770 (rwxrwx---)
INFO: Avahi - completing the configuration in /etc/avahi/services/smbd.service...
INFO: running test for xattr support on your time machine persistent storage location...
INFO: xattr test successful - your persistent data store supports xattrs
INFO: Detected filesystem for /opt/timemachine is xfs
INFO: entrypoint complete; executing 's6-svscan /etc/s6'

Just want to make sure that it isn't having issues setting any permissions.

Also, what's the host os? a docker info would get me all the info I am looking for and then some.

Piwares commented 9 months ago

Docker log is here: INFO: CUSTOM_SMB_CONF=false; generating [global] section of /etc/samba/smb.conf... INFO: Creating /var/log/samba/cores INFO: Avahi - generating base configuration in /etc/avahi/services/smbd.service... INFO: Avahi - adding the 'dk0', 'TimeMachine' share txt-record to /etc/avahi/services/smbd.service... INFO: Group piwares doesn't exist; creating... INFO: User piwares doesn't exist; creating... INFO: Setting password from environment variable INFO: INFO: CUSTOM_SMB_CONF=false; generating [TimeMachine] section of /etc/samba/smb.conf... INFO: Samba - Created Added user piwares. INFO: Samba - Enabled user piwares. INFO: Samba - setting password INFO: changed ownership of '/opt/piwares' to 1000:1000 INFO: mode of '/opt/piwares' changed to 0770 (rwxrwx---) INFO: Avahi - completing the configuration in /etc/avahi/services/smbd.service... INFO: running test for xattr support on your time machine persistent storage location... INFO: xattr test successful - your persistent data store supports xattrs INFO: Detected filesystem for /opt/piwares is xfs INFO: entrypoint complete; executing 's6-svscan /etc/s6' Docker info: Containers: 1 Running: 1 Paused: 0 Stopped: 0 Images: 3 Server Version: 18.09.0 Storage Driver: devicemapper Pool Name: klash-thinpool Pool Blocksize: 524.3kB Base Device Size: 10.74GB Backing Filesystem: xfs Udev Sync Supported: true Data Space Used: 1.116GB Data Space Total: 63.83GB Data Space Available: 62.71GB Metadata Space Used: 17.45MB Metadata Space Total: 6.38GB Metadata Space Available: 6.362GB Thin Pool Minimum Free Space: 6.383GB Deferred Removal Enabled: true Deferred Deletion Enabled: true Deferred Deleted Device Count: 0 Library Version: 1.02.171 (2020-03-26) Semaphore Set Used: 1 Semaphore Set Total: 32000 Logging Driver: json-file Cgroup Driver: cgroupfs Hugetlb Pagesize: 2MB Plugins: Volume: local lvm Network: bridge host macvlan null overlay Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog Swarm: inactive Runtimes: runc Default Runtime: runc Init Binary: docker-init containerd version: runc version: N/A init version: N/A (expected: ) Security Options: seccomp Profile: default Kernel Version: 4.19.90-52.25.v2207.ky10.x86_64 Operating System: Kylin Linux Advanced Server Host V10 (Kivity) OSType: linux Architecture: x86_64 CPUs: 4 Total Memory: 14.37GiB Name: localhost.localdomain ID: FGJW:VTLY:KBIN:LWVO:VCYA:QQQO:NIUW:DFYM:C3YH:HZ2Q:HIH2:WBIL Docker Root Dir: /var/lib/docker Debug Mode (client): false Debug Mode (server): false Registry: https://index.docker.io/v1/ Labels: Experimental: false Insecure Registries: 127.0.0.0/8 Registry Mirrors: https://mghfk16c.mirror.aliyuncs.com/ Live Restore Enabled: true

Piwares commented 9 months ago

I was puzzled for these log information: smbd_dirptr_get_entry mask=[] found 62F78F8B-6EEA-50EF-A37F-5D95F8DA221E.sparsebundle/. fname=. (.) synthetic_pathref: opening [62F78F8B-6EEA-50EF-A37F-5D95F8DA221E.sparsebundle/.:AFP_AfpInfo] failed smbd_dirptr_get_entry mask=[] found 62F78F8B-6EEA-50EF-A37F-5D95F8DA221E.sparsebundle/.. fname=.. (..) synthetic_pathref: opening [62F78F8B-6EEA-50EF-A37F-5D95F8DA221E.sparsebundle/..:AFP_AfpInfo] failed

I'm using smb, but why AFP_AfpInfo displayed in the log?

mbentley commented 9 months ago

With time machine backup logs, I often seen quite a few messages that initially look like errors but they're more informative. As far as I know, time machine backups still support AFP so it may just be checking a sparsebundle for afp support.

mbentley commented 9 months ago

So trimming down the client logs, it really comes down to this:

2023-12-28 22:15:08.335755+0800 0x1d6528f  Error   com.apple.backupd.xpc: connection invalid
2023-12-28 22:15:08.337778+0800 0x1d653ed  Info    Backup requested to next destination in rotation. specifiedOptions: TMBackupOptions(rawValue: 1)
2023-12-28 22:15:08.354435+0800 0x1d653ed  Info    Not prioritizing backups with priority errors. lockState=0
2023-12-28 22:15:08.357264+0800 0x1d653ee  Info    Starting backup with mode "automatic backup"
2023-12-28 22:15:08.381029+0800 0x1d65400  Info    Rejecting candidate mount point: /Volumes/TimeMachine, not owned by root
2023-12-28 22:15:08.382141+0800 0x1d65400  Info    Attempting to mount 'smb://piwares@192.168.2.1/TimeMachine'
2023-12-28 22:15:09.227867+0800 0x1d65400  Info    Initial network volume options for 'TimeMachine' {disablePrimaryReconnect: 0, disableSecondaryReconnect: 0, reconnectTimeOut: 0, QoS: 0x0, attributes: 0x1C}
2023-12-28 22:15:09.446558+0800 0x1d65400  Info    Configured network volume options for 'TimeMachine' {disablePrimaryReconnect: 0, disableSecondaryReconnect: 0, reconnectTimeOut: 30, QoS: 0x20, attributes: 0x1C}
2023-12-28 22:15:09.453251+0800 0x1d65400  Info    Mounted 'smb://piwares@192.168.2.1/TimeMachine' at '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine' (319.69 GB of 321.97 GB available)
2023-12-28 22:15:09.666158+0800 0x1d65400  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine' is still valid
2023-12-28 22:15:09.912600+0800 0x1d65400  Info    Creating an unencrypted diskimage
2023-12-28 22:15:09.912755+0800 0x1d65400  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine' is still valid
2023-12-28 22:15:09.921192+0800 0x1d65400  Info    Using a band size of 78.6 MB (on a volume with size of 321.97 GB)
2023-12-28 22:15:09.994102+0800 0x1d65400  Error   Failed to create disk image at '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-28-221509.sparsebundle', error: Error Domain=NSPOSIXErrorDomain Code=13 "Permission denied" UserInfo={DIErrorVerboseInfo=Failed creating the image: Failed creating bands folder}
2023-12-28 22:15:10.005120+0800 0x1d65400  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine' is still valid
2023-12-28 22:15:10.005469+0800 0x1d65400  Info    Evaluating to see if an unmount was responsible for error: Error Domain=com.apple.backupd.ErrorDomain Code=20 "(null)" UserInfo={NSUnderlyingError=0x12df1ebf0 {Error Domain=NSPOSIXErrorDomain Code=13 "Permission denied" UserInfo={DIErrorVerboseInfo=Failed creating the image: Failed creating bands folder}}}
2023-12-28 22:15:10.006555+0800 0x1d653ef  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine' is still valid
2023-12-28 22:15:10.217351+0800 0x1d65400  Info    Unmounted '/Volumes/.timemachine/192.168.2.1/1FA7F248-3B44-4A94-9989-0CCCD837E349/TimeMachine'
2023-12-28 22:15:10.234548+0800 0x1d65432  Error   com.apple.TMHelperAgent.DeliverNotification: connection invalid
2023-12-28 22:15:10.234868+0800 0x1d65401  Info    Finished rotating through all destinations
2023-12-28 22:15:10.237058+0800 0x1d653ed  Error   Backup failed: BACKUP_FAILED_DISK_IMAGE_NOT_CREATED (20)
2023-12-28 22:15:10.237154+0800 0x1d653ed  Error   Analytics send failed.

To remove the possibility of the volume driver being an issue, do you have a location where you could bind mount with an existing filesystem to just test the ability to back up without it?

Piwares commented 9 months ago

Unfortunetly, it is not the cause of volume driver. The erros still exists.

client.log is:

2023-12-29 19:47:31.095444+0800 0x1dccd75  Error   Analytics send failed.
2023-12-29 19:47:42.452776+0800 0x1dcb17a  Info    TMPowerState: 2
2023-12-29 19:47:42.456075+0800 0x1dcce08  Info    Backup requested to next destination in rotation. specifiedOptions: TMBackupOptions(rawValue: 1)
2023-12-29 19:47:42.456094+0800 0x1dccedb  Error   com.apple.backupd.xpc: connection invalid
2023-12-29 19:47:42.472301+0800 0x1dcce08  Info    Not prioritizing backups with priority errors. lockState=0
2023-12-29 19:47:42.474350+0800 0x1dcce08  Info    Starting backup with mode "automatic backup"
2023-12-29 19:47:42.503562+0800 0x1dcce08  Info    Rejecting candidate mount point: /Volumes/TimeMachine, not owned by root
2023-12-29 19:47:42.505039+0800 0x1dcce08  Info    Attempting to mount 'smb://piwares@192.168.2.1/TimeMachine'
2023-12-29 19:47:42.864051+0800 0x1dcce08  Info    Initial network volume options for 'TimeMachine' {disablePrimaryReconnect: 0, disableSecondaryReconnect: 0, reconnectTimeOut: 0, QoS: 0x0, attributes: 0x1C}
2023-12-29 19:47:43.074883+0800 0x1dcce08  Info    Configured network volume options for 'TimeMachine' {disablePrimaryReconnect: 0, disableSecondaryReconnect: 0, reconnectTimeOut: 30, QoS: 0x20, attributes: 0x1C}
2023-12-29 19:47:43.079125+0800 0x1dcce08  Info    Mounted 'smb://piwares@192.168.2.1/TimeMachine' at '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine' (52.68 GB of 62.43 GB available)
2023-12-29 19:47:43.291648+0800 0x1dcce08  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine' is still valid
2023-12-29 19:47:43.525616+0800 0x1dcce08  Info    Creating an unencrypted diskimage
2023-12-29 19:47:43.525803+0800 0x1dcce08  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine' is still valid
2023-12-29 19:47:43.529319+0800 0x1dcce08  Info    Using a band size of 15.2 MB (on a volume with size of 62.43 GB)
2023-12-29 19:47:43.577517+0800 0x1dcce08  Error   Failed to create disk image at '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle', error: Error Domain=NSPOSIXErrorDomain Code=13 "Permission denied" UserInfo={DIErrorVerboseInfo=Failed creating the image: Failed creating bands folder}
2023-12-29 19:47:43.590377+0800 0x1dcce08  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine' is still valid
2023-12-29 19:47:43.590647+0800 0x1dcce08  Info    Evaluating to see if an unmount was responsible for error: Error Domain=com.apple.backupd.ErrorDomain Code=20 "(null)" UserInfo={NSUnderlyingError=0x12f00a5b0 {Error Domain=NSPOSIXErrorDomain Code=13 "Permission denied" UserInfo={DIErrorVerboseInfo=Failed creating the image: Failed creating bands folder}}}
2023-12-29 19:47:43.590940+0800 0x1dccedb  Info    Mountpoint '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine' is still valid
2023-12-29 19:47:43.801066+0800 0x1dcce08  Info    Unmounted '/Volumes/.timemachine/192.168.2.1/21D1528A-49F8-4D97-9949-BE38E23E486C/TimeMachine'
2023-12-29 19:47:43.822730+0800 0x1dccf1e  Error   com.apple.TMHelperAgent.DeliverNotification: connection invalid
2023-12-29 19:47:43.822896+0800 0x1dccf0d  Info    Finished rotating through all destinations
2023-12-29 19:47:43.826732+0800 0x1dccee5  Error   Backup failed: BACKUP_FAILED_DISK_IMAGE_NOT_CREATED (20)
2023-12-29 19:47:43.826824+0800 0x1dccee5  Error   Analytics send failed.
</code>

container log is:
<code>
INFO: Current debug levels:
  all: 7
  tdb: 7
  printdrivers: 7
  lanman: 7
  smb: 7
  rpc_parse: 7
  rpc_srv: 7
  rpc_cli: 7
  passdb: 7
  sam: 7
  auth: 7
  winbind: 7
  vfs: 7
  idmap: 7
  quota: 7
  acls: 7
  locking: 7
  msdfs: 7
  dmapi: 7
  registry: 7
  scavenger: 7
  dns: 7
  ldb: 7
  tevent: 7
  auth_audit: 7
  auth_json_audit: 7
  kerberos: 7
  drs_repl: 7
  smb2: 7
  smb2_credits: 7
  dsdb_audit: 7
  dsdb_json_audit: 7
  dsdb_password_audit: 7
  dsdb_password_json_audit: 7
  dsdb_transaction_audit: 7
  dsdb_transaction_json_audit: 7
  dsdb_group_audit: 7
  dsdb_group_json_audit: 7
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle, access_mask = 0x81, share_access = 0x7 create_options = 0x1, create_disposition = 0x2, file_attributes = 0x10
unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle) inherit mode 40770
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle) returning 040770
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle], expect_close = 0
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle], expect_close = 0
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle/. fname=. (.)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle/.:AFP_AfpInfo] failed
fget_ea_dos_attribute: Cannot get attribute from EA on file 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle/..: Error = No data available
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle/.. fname=.. (..)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle/..:AFP_AfpInfo] failed
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle, access_mask = 0x110080, share_access = 0x0 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
smbd_do_setfilepathinfo: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle (fnum 1970001197) info_level=1013 totdata=1
close_directory: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194730.sparsebundle. Delete on close was set - deleting directory returned NT_STATUS_OK.
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle, access_mask = 0x81, share_access = 0x7 create_options = 0x1, create_disposition = 0x2, file_attributes = 0x10
unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle) inherit mode 40770
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle) returning 040770
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle], expect_close = 0
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle], expect_close = 0
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle/. fname=. (.)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle/.:AFP_AfpInfo] failed
fget_ea_dos_attribute: Cannot get attribute from EA on file 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle/..: Error = No data available
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle/.. fname=.. (..)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle/..:AFP_AfpInfo] failed
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle, access_mask = 0x110080, share_access = 0x0 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
smbd_do_setfilepathinfo: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle (fnum 845425123) info_level=1013 totdata=1
close_directory: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-194743.sparsebundle. Delete on close was set - deleting directory returned NT_STATUS_OK.

Seem nothing has changed.

mbentley commented 9 months ago

Hmm, try setting the env var for SMB_VFS_OBJECTS to acl_xattr fruit streams_xattr and see if that makes any difference.

Piwares commented 9 months ago

It is the same result.

container log: 

open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle, access_mask = 0x81, share_access = 0x7 create_options = 0x1, create_disposition = 0x2, file_attributes = 0x10
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle) returning 0755
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle) returning 0755
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle) returning 0744
store_acl_blob_fsp: setting attr failed for file 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundlewith error Operation not permitted
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle], expect_close = 0
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle, access_mask = 0x100081, share_access = 0x7 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
dptr_create: dir=6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
dptr_create: creating new dirptr [0] for path [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle], expect_close = 0
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/. fname=. (.)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/.:AFP_AfpInfo] failed
fget_ea_dos_attribute: Cannot get attribute from EA on file 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/..: Error = No data available
smbd_dirptr_get_entry mask=[*] found 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/.. fname=.. (..)
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir to 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
vfs_ChDir: vfs_ChDir got /opt/piwares/6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle
synthetic_pathref: opening [6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/..:AFP_AfpInfo] failed
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/..) returning 0755
unix_mode: unix_mode(6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle/..) returning 0744
open_directory: opening directory 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle, access_mask = 0x110080, share_access = 0x0 create_options = 0x1, create_disposition = 0x1, file_attributes = 0x10
smbd_do_setfilepathinfo: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle (fnum 1933170511) info_level=1013 totdata=1
close_directory: 6E4A8E78-46AD-51A2-AD0A-EEAB7F1E1746_2023-12-29-203850.sparsebundle. Delete on close was set - deleting directory returned NT_STATUS_OK.
Piwares commented 9 months ago

Is the problem caused by kernel or docker version which are not compatibable with smb or netatalk？

mbentley commented 9 months ago

So, I am trying to see if I can find anything that sticks out error wise and I came across this: https://discuss.linuxcontainers.org/t/setting-extended-attributes-failed-reason-operation-not-permitted/10670/3

So it may be that there is an issue with the allowed syscalls that may be blocking things. A quick and dirty test would be to add the --privileged flag to allow the container to bypass any potential restrictions. This might be something that would have been addressed with a newer version of Docker if it does work with --privileged. I suppose it could also be an out of date version of seccomp which would also be bypassed when using --privileged.

I have no idea if looking at the Docker daemon logs or the system logs (like syslog or whatever logging mechanism your OS uses) would show a blocking of some sort of syscall.

Piwares commented 9 months ago

A good news is that, using --privileged flag, it started to backup successfully. This just solved my problem. It seems that the problem of blocking syscall. If you want to dig it more, i can provide the os image for you to check, or i'll close the case.

mbentley commented 9 months ago

I would say that it is probably just better to just close the issue.

If you want to troubleshoot further, you can try a few things:

If setting seccomp to unconfined works, you can see if there is a newer package for seccomp available for your distribution. But if you are find running the container as --privileged, then that's fine by me.