Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

internal error: signal 11 - when saving word or excel files #357

Closed
ITelligencia opened this issue Jun 16, 2023 · 39 comments
Closed

internal error: signal 11 - when saving word or excel files #357

ITelligencia opened this issue Jun 16, 2023 · 39 comments
Assignees

Comments

@ITelligencia
Copy link

Similar to issue described on the admin list, but here users have no problem authenticating.

Hi,

After updating our ubuntu 20.04 ubuntu fileserver, netatalk stopped working - or rather, clients are unable to save microsoft 365 files.

I started again on a fresh ubuntu 23.04 server (also tried 22.04), but
Word and Excel on mac (M1 and M2) clients hang when saving files. Initially installed netatalk via apt, then moved on to the latest version, 3.1.15, as I understood this issue was fixed from 3.1.14.

I used the following configure options:

./configure
--with-init-style=debian-systemd
--without-libevent
--without-tdb
--with-cracklib
--enable-krbV-uam
--with-pam-confdir=/etc/pam.d
--with-dbus-daemon=/usr/bin/dbus-daemon
-—with-dbus-sysconf-dir=/etc/dbus-1/system.d
--with-tracker-pkgconfig-version=3.0

afp.conf:

[Global]
max connections = 1000
zeroconf = yes
hostname = netatalk
;nodebug = yes
vol preset = my default values

[my default values]
ea = samba
;convert appledouble = no

[Backups and Clones]
path = /volume1/Backups_and_Clones
valid users = @users
directory perm = 0775
file perm =0664

/var/log/syslog:

2023-06-16T10:11:54.282523-06:00 netatalk afpd[1292]: INTERNAL ERROR: Signal 11 in pid 1292 (3.1.15)
2023-06-16T10:11:54.282686-06:00 netatalk afpd[1292]: ===============================================================
2023-06-16T10:11:54.282888-06:00 netatalk afpd[1292]: PANIC: internal error
2023-06-16T10:11:54.283917-06:00 netatalk afpd[1292]: BACKTRACE: 11 stack frames:
2023-06-16T10:11:54.284215-06:00 netatalk afpd[1292]: #0 /usr/local/lib/libatalk.so.18(netatalk_panic+0x39) [0x7fb364eeda69]
2023-06-16T10:11:54.284304-06:00 netatalk afpd[1292]: #1 /usr/local/lib/libatalk.so.18(+0x3abbe) [0x7fb364eedbbe]
2023-06-16T10:11:54.284423-06:00 netatalk afpd[1292]: #2 /lib/x86_64-linux-gnu/libc.so.6(+0x3c4b0) [0x7fb36483c4b0]
2023-06-16T10:11:54.284514-06:00 netatalk afpd[1292]: #3 /lib/x86_64-linux-gnu/libc.so.6(+0x170e2c) [0x7fb364970e2c]
2023-06-16T10:11:54.284598-06:00 netatalk afpd[1292]: #4 /usr/local/lib/libatalk.so.18(ad_copy_header+0x55) [0x7fb364ecae45]
2023-06-16T10:11:54.284799-06:00 netatalk afpd[1292]: #5 /usr/local/sbin/afpd(afp_exchangefiles+0x758) [0x563d4afcdf78]
2023-06-16T10:11:54.284917-06:00 netatalk afpd[1292]: #6 /usr/local/sbin/afpd(afp_over_dsi+0x57b) [0x563d4afb7b0b]
2023-06-16T10:11:54.285008-06:00 netatalk afpd[1292]: #7 /usr/local/sbin/afpd(main+0x9af) [0x563d4afb5aaf]
2023-06-16T10:11:54.285114-06:00 netatalk afpd[1292]: #8 /lib/x86_64-linux-gnu/libc.so.6(+0x23a90) [0x7fb364823a90]
2023-06-16T10:11:54.285220-06:00 netatalk afpd[1292]: #9 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x89) [0x7fb364823b49]
2023-06-16T10:11:54.285328-06:00 netatalk afpd[1292]: #10 /usr/local/sbin/afpd(_start+0x25) [0x563d4afb5e05]

@rdmark
Copy link
Member

rdmark commented Jun 18, 2023

For the record, this is the stacktrace shared by Reindl Harald on the list:

May  9 12:34:30 fileserver afpd[603892]:
===============================================================
May  9 12:34:30 fileserver afpd[603892]: INTERNAL ERROR: Signal 11 in
pid 603892 (3.1.15)
May  9 12:34:30 fileserver afpd[603892]:
===============================================================
May  9 12:34:30 fileserver afpd[603892]: PANIC: internal error
May  9 12:34:30 fileserver afpd[603892]: BACKTRACE: 11 stack frames:
May  9 12:34:30 fileserver afpd[603892]: #0
/lib64/libatalk.so.18(netatalk_panic+0x35) [0x7f8588faf7e5]
May  9 12:34:30 fileserver afpd[603892]: #1
/lib64/libatalk.so.18(+0x3192a) [0x7f8588faf92a]
May  9 12:34:30 fileserver afpd[603892]: #2 /lib64/libc.so.6(+0x3cb20)
[0x7f8588dd3b20]
May  9 12:34:30 fileserver afpd[603892]: #3 /lib64/libc.so.6(+0x163e70)
[0x7f8588efae70]
May  9 12:34:30 fileserver afpd[603892]: #4
/lib64/libatalk.so.18(ad_copy_header+0x4d) [0x7f8588f8e54d]
May  9 12:34:30 fileserver afpd[603892]: #5
/usr/sbin/afpd(afp_exchangefiles+0x7ac) [0x55df96663e9c]
May  9 12:34:30 fileserver afpd[603892]: #6
/usr/sbin/afpd(afp_over_dsi+0x63e) [0x55df96655d8e]
May  9 12:34:30 fileserver afpd[603892]: #7 /usr/sbin/afpd(main+0x9ad)
[0x55df9664ce0d]
May  9 12:34:30 fileserver afpd[603892]: #8 /lib64/libc.so.6(+0x27510)
[0x7f8588dbe510]
May  9 12:34:30 fileserver afpd[603892]: #9
/lib64/libc.so.6(__libc_start_main+0x89) [0x7f8588dbe5c9]
May  9 12:34:30 fileserver afpd[603892]: #10 /usr/sbin/afpd(_start+0x25)
[0x55df9664d155]
May  9 12:34:31 fileserver afpd[603897]: Login by **** (AFP3.4)
May  9 12:34:31 fileserver afpd[122331]: Reconnect: no child[603892]
May  9 12:34:36 fileserver afpd[603897]: afp_disconnect: primary
reconnect failed
May  9 12:34:36 fileserver afpd[603897]:
===============================================================
May  9 12:34:36 fileserver afpd[603897]: INTERNAL ERROR: Signal 11 in
pid 603897 (3.1.15)
May  9 12:34:36 fileserver afpd[603897]:
===============================================================
May  9 12:34:36 fileserver afpd[603897]: PANIC: internal error
May  9 12:34:36 fileserver afpd[603897]: BACKTRACE: 11 stack frames:
May  9 12:34:36 fileserver afpd[603897]: #0
/lib64/libatalk.so.18(netatalk_panic+0x35) [0x7f8588faf7e5]
May  9 12:34:36 fileserver afpd[603897]: #1
/lib64/libatalk.so.18(+0x3192a) [0x7f8588faf92a]
May  9 12:34:36 fileserver afpd[603897]: #2 /lib64/libc.so.6(+0x3cb20)
[0x7f8588dd3b20]
May  9 12:34:36 fileserver afpd[603897]: #3 /lib64/libc.so.6(+0x163e70)
[0x7f8588efae70]
May  9 12:34:36 fileserver afpd[603897]: #4
/lib64/libatalk.so.18(ad_copy_header+0x4d) [0x7f8588f8e54d]
May  9 12:34:36 fileserver afpd[603897]: #5
/usr/sbin/afpd(afp_exchangefiles+0x7ac) [0x55df96663e9c]
May  9 12:34:36 fileserver afpd[603897]: #6
/usr/sbin/afpd(afp_over_dsi+0x63e) [0x55df96655d8e]
May  9 12:34:36 fileserver afpd[603897]: #7 /usr/sbin/afpd(main+0x9ad)
[0x55df9664ce0d]
May  9 12:34:36 fileserver afpd[603897]: #8 /lib64/libc.so.6(+0x27510)
[0x7f8588dbe510]
May  9 12:34:36 fileserver afpd[603897]: #9
/lib64/libc.so.6(__libc_start_main+0x89) [0x7f8588dbe5c9]
May  9 12:34:36 fileserver afpd[603897]: #10 /usr/sbin/afpd(_start+0x25)
[0x55df9664d155]
May  9 12:34:37 fileserver afpd[603902]: Login by **** (AFP3.4)
May  9 12:34:37 fileserver afpd[122331]: Reconnect: no child[603897]
May  9 12:34:42 fileserver afpd[603902]: afp_disconnect: primary
reconnect failed

@rdmark
Copy link
Member

rdmark commented Jun 18, 2023

@ITelligencia With which netatalk version did this usecase last work?

BTW, this doesn't have any bearing with the current issue, but you don't need to use the --without-libevent configure flag anymore, since the bundled libevent has been removed altogether with 3.1.13 and later.

@rdmark
Copy link
Member

rdmark commented Jul 6, 2023

@ITelligencia so I tried to replicate your environment as much as possible (although with Debian Bullseye), using similar afp.conf settings, and running the latest Office 365 native Mac apps. I was able to save docx and xlsx files from the Mac onto multiple netatalk AFP shares without encountering errors. So there must be something else environmental in your setup. For instance, are you using a file system that is not ext4?

Would it be possible to get debug logs from netatalk leading up to the crash? You can set log level = default:debug in afp.conf

@dpm3354
Copy link

dpm3354 commented Jul 11, 2023

Hello, I believe I'm experiencing the issue mentioned here, but I'm not a linux/netatalk expert.

MS Word Freezes on Mac M1 when saving/closing files located on netatalk fileserver.

Client Environment:

  • Apple M1 Pro
  • Ventura 13.4.1 (a)

File server Environment:

  • No LSB modules are available.
  • Distributor ID: Ubuntu
  • Description: Ubuntu 22.04.2 LTS
  • Release: 22.04
  • Codename: jammy
  • netatalk 3.1.12

Stack trace:

Jul 10 21:27:48 merrill-nfs afpd[2951]: ad_open_hf_ea: unexpected: Invalid argument
Jul 10 21:27:48 merrill-nfs afpd[6256]: ===============================================================
Jul 10 21:27:48 merrill-nfs afpd[6256]: INTERNAL ERROR: Signal 11 in pid 6256 (3.1.12)
Jul 10 21:27:48 merrill-nfs afpd[6256]: ===============================================================
Jul 10 21:27:48 merrill-nfs afpd[6256]: PANIC: internal error
Jul 10 21:27:48 merrill-nfs afpd[6256]: BACKTRACE: 11 stack frames:
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #0 /lib/x86_64-linux-gnu/libatalk.so.18(netatalk_panic+0x39) [0x7f9708781489]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #1 /lib/x86_64-linux-gnu/libatalk.so.18(+0x315de) [0x7f97087815de]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #2 /lib/x86_64-linux-gnu/libc.so.6(+0x42520) [0x7f97080e3520]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #3 /lib/x86_64-linux-gnu/libc.so.6(+0xc4a1b) [0x7f9708165a1b]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #4 /lib/x86_64-linux-gnu/libatalk.so.18(ad_copy_header+0x6c) [0x7f970876223c]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #5 /usr/sbin/afpd(afp_exchangefiles+0x750) [0x5593e97b5d30]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #6 /usr/sbin/afpd(afp_over_dsi+0x599) [0x5593e979fc59]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #7 /usr/sbin/afpd(main+0x9ae) [0x5593e979dbde]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #8 /lib/x86_64-linux-gnu/libc.so.6(+0x29d90) [0x7f97080cad90]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #9 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x80) [0x7f97080cae40]
Jul 10 21:27:48 merrill-nfs afpd[6256]:  #10 /usr/sbin/afpd(_start+0x25) [0x5593e979df25]

Additionally, I don't know if this is helpful, but I see in the dpkg logs an upgrade to netatalk around the time this started in early June 2023...

upgrade netatalk:amd64 3.1.12~ds-9build1 3.1.12~ds-9ubuntu0.22.04.1

Any help resolving, including work-arounds is helpful.

@dpm3354
Copy link

dpm3354 commented Jul 11, 2023

UPDATE - after downgrading to netatalk 3.1.12~ds-9build1 the issue is resolved for me.

@ITelligencia
Copy link
Author

ITelligencia commented Jul 11, 2023 via email

@rdmark
Copy link
Member

rdmark commented Jul 11, 2023

Thanks for sharing the additional context. Let me set up an Ubuntu VM to see what patches they applied to 3.1.12~ds-9ubuntu0.22.04.1. My guess is that it's the same set of security patches that applies stricter validation of meta data headers.

In the meantime, it'd love it if you could provide me with debug logs leading up to the crash. This would help immensely with pinpointing the source of the problem.

@rdmark
Copy link
Member

rdmark commented Jul 11, 2023

Confirmed that the latest Ubuntu package pulls in the entire range of security patches contained in 3.1.15:

dpkg-source: info: extracting netatalk in netatalk-3.1.12~ds
dpkg-source: info: unpacking netatalk_3.1.12~ds.orig.tar.xz
dpkg-source: info: unpacking netatalk_3.1.12~ds-9ubuntu0.22.04.1.debian.tar.xz
dpkg-source: info: using patch list from debian/patches/series
dpkg-source: info: applying 100~20160429~b30a2ba.patch
dpkg-source: info: applying 100~20180418~db60d06.patch
dpkg-source: info: applying 100~20180427~57e96d1.patch
dpkg-source: info: applying 100~20200122~32df6e1.patch
dpkg-source: info: applying 100~20200330~0235275.patch
dpkg-source: info: applying 100~20200330~3bb7423.patch
dpkg-source: info: applying 100~20200331~fd1d016.patch
dpkg-source: info: applying 101_shared_libs.patch
dpkg-source: info: applying 102_python3.patch
dpkg-source: info: applying 103_fix_typos.patch
dpkg-source: info: applying 104_modernize_systemd.patch
dpkg-source: info: applying 105_cross-compilation.patch
dpkg-source: info: applying 106_fix_BerkeleyDB_multiarch_support.patch
dpkg-source: info: applying 107_allow_use_of_tirpc.patch
dpkg-source: info: applying 114_fix_macusers_ps_parsing.patch
dpkg-source: info: applying 201_embedded_libs.patch
dpkg-source: info: applying 203_init_lsb.patch
dpkg-source: info: applying 204_statedir.patch
dpkg-source: info: applying 205_add-support-for-tracker3.patch
dpkg-source: info: applying CVE-2021-31439.patch
dpkg-source: info: applying CVE-2022-0194_23122_23123_23124_part1.patch
dpkg-source: info: applying CVE-2022-0194_23122_23123_23124_part2.patch
dpkg-source: info: applying CVE-2022-0194_23122_23123_23124_part3.patch
dpkg-source: info: applying CVE-2022-0194_23122_23123_23124_part4.patch
dpkg-source: info: applying CVE-2022-0194_23122_23123_23124_part5.patch
dpkg-source: info: applying CVE-2022-23121.patch
dpkg-source: info: applying CVE-2022-23121_regression.patch
dpkg-source: info: applying CVE-2022-23125.patch
dpkg-source: info: applying CVE-2022-43634.patch
dpkg-source: info: applying CVE-2022-45188.patch

compared to

dpkg-source: info: extracting netatalk in netatalk-3.1.12~ds
dpkg-source: info: unpacking netatalk_3.1.12~ds.orig.tar.xz
dpkg-source: info: unpacking netatalk_3.1.12~ds-9build1.debian.tar.xz
dpkg-source: info: using patch list from debian/patches/series
dpkg-source: info: applying 100~20160429~b30a2ba.patch
dpkg-source: info: applying 100~20180418~db60d06.patch
dpkg-source: info: applying 100~20180427~57e96d1.patch
dpkg-source: info: applying 100~20200122~32df6e1.patch
dpkg-source: info: applying 100~20200330~0235275.patch
dpkg-source: info: applying 100~20200330~3bb7423.patch
dpkg-source: info: applying 100~20200331~fd1d016.patch
dpkg-source: info: applying 101_shared_libs.patch
dpkg-source: info: applying 102_python3.patch
dpkg-source: info: applying 103_fix_typos.patch
dpkg-source: info: applying 104_modernize_systemd.patch
dpkg-source: info: applying 105_cross-compilation.patch
dpkg-source: info: applying 106_fix_BerkeleyDB_multiarch_support.patch
dpkg-source: info: applying 107_allow_use_of_tirpc.patch
dpkg-source: info: applying 114_fix_macusers_ps_parsing.patch
dpkg-source: info: applying 201_embedded_libs.patch
dpkg-source: info: applying 203_init_lsb.patch
dpkg-source: info: applying 204_statedir.patch
dpkg-source: info: applying 205_add-support-for-tracker3.patch

So this issue is very likely falling under the same umbrella as #236

@rdmark
Copy link
Member

rdmark commented Jul 11, 2023

@dpm3354 Would you be able to share the contents of your afp.conf with me as well?

Also, how are your shared volumes configured? Are they on the same file system as the Linux system, or on external storage media somehow?

@dpm3354
Copy link

dpm3354 commented Jul 12, 2023

Hi @rdmark - my afp.conf file below. I've changed the name of the mountpoint and user to amountpoint and auser, respectively.

Additionally, you asked for debug logs from before the crash. I'm not familiar with what you mean. Is that from syslog, just earlier in the trace that I already provided? Or is that something else, something I would need to recreate for you? I'm not able to spend much time helping, unfortunately, but if it's easy, I'm happy to send.

;
; Netatalk 3.x configuration file
;

[Global]
; Global server settings

; [Homes]
; basedir regex = /xxxx

; [My AFP Volume]
; path = /path/to/volume

; [My Time Machine Volume]
; path = /path/to/backup
; time machine = yes

[Time Machine]
  path = /mnt/amountpoint/shares/TimeMachineBackup
  time machine = yes

[Homes]
  basedir regex = /home

[amountpoint]
  path = /mnt/amountpoint
  time machine = yes

[auser]
  path = /home/auser


@rdmark
Copy link
Member

rdmark commented Jul 12, 2023

@dpm3354 thanks for this! You really don't do anything fancy in your afp.conf so these settings are clearly not the differentiator.

Yes by logs, I mean syslog. For one, I'd love to see the ~100 lines that lead up to the crash. Additionally if you have the time, by putting log level = default:debug under the [Global] settings you will get a ton more granular logs in syslog. If you could get me the debug logs from when a user tried to connect until the crash, that would be super helpful.

@ITelligencia
Copy link
Author

Hi rdmark,

On my test server, once I upgrade to the latest netatalk package (3.1.12 on ubuntu server 22.04), then reconnect from my mac, the syslog immediately starts spewing errors. I have attached a syslog excerpt from during the updating (nothing interesting) and then an excerpt with the errors right after the update - it basically keeps repeating the last error, while Word hangs as it can't finalise saving the doc.
syslogduringupdates.txt
syslogrightafterupdates.txt

There is a very basic afp.conf:

; Netatalk 3.x configuration file
;

[Global]
; Global server settings
level = default:debug
; [Homes]
; basedir regex = /xxxx

[testruben]
path = /opt/testruben

@ITelligencia
Copy link
Author

on this test server, /opt/testruben is not on a different drive.

settings in fstab:
/ ext4 defaults,user_xattr,acl 0 1

@rdmark
Copy link
Member

rdmark commented Jul 13, 2023

@ITelligencia This is very helpful, thank you! The syslogrightafterupdates.txt logs confirm that the failure is in the same EA header validation code. The behavior is slightly different since you're actually getting an assert and coredump, whereas the other issue ticket is for when afpd keeps running and throws a ad_open_hf_ea: unexpected: Invalid argument error instead of crashing. I'll keep both issue tickets open for now.

The one lead here is that you have xattr and ACL enabled for your file system, which I don't. Both are types of extended attributes, so there's a good chance that this is what makes the difference!

@rdmark
Copy link
Member

rdmark commented Jul 15, 2023

Okay I was able to reproduce this issue now. What I did was to add the user_xattr option to my fstab and remount the file system. Now saving an Office 365 Word docx triggers the bug. Strangely enough, even after removing the user_xattr option again the issue still persists, so something must have been altered permanently on this ext4 file system by this option?

Even more curiously, the xattr man page suggests that you shouldn't even use the user_xattr option with an ext4 file system. If I read the man page correctly, it's a legacy option to enable EAs on reiserfs and legacy ext variants. Could anyone more knowledgeable here confirm or refute this?

@slowfranklin
Copy link
Member

slowfranklin commented Jul 15, 2023 via email

@rdmark
Copy link
Member

rdmark commented Jul 30, 2023

Thanks @slowfranklin , that's a helpful troubleshooting method. I spotted the getfattr command as well for printing current attributes. BTW on Debian Bookworm I needed to install the attr package to get these tools.

Now, what seems to happen when saving the Word/Excel file, is that the application stores temporary files in a new temp dir, which I believe should be converted to a macOS bundle afterwards, but this process fails and it stays a temp dir and netatalk crashes. My additional logging gives the error ad_entry(): invalid size 16 bytes but there are a bunch of failed CNID operations above that. I got lost in the code when I tried to figure out exactly what was going on, but I'll keep looking at it when I have time.

This is the complete debug log.

Jul 13 20:37:40 bookworm cnid_metad[911]: user: dmark, volume Homes, path /home/dmark/afp-data
Jul 13 20:37:40 bookworm cnid_metad[911]: load_volumes: BEGIN
Jul 13 20:37:40 bookworm cnid_metad[911]: load_volumes: no volumes yet
Jul 13 20:37:40 bookworm cnid_metad[911]: load_volumes: loading: /usr/local/etc/afp.conf
Jul 13 20:37:40 bookworm cnid_metad[911]: readvolfile: BEGIN
Jul 13 20:37:40 bookworm cnid_metad[911]: readvolfile: sections: 2
Jul 13 20:37:40 bookworm cnid_metad[911]: load_volumes: END
Jul 13 20:37:40 bookworm cnid_metad[911]: getvolbypath("/home/dmark/afp-data")
Jul 13 20:37:40 bookworm cnid_metad[911]: getvolbypath: user home section: 'Homes', basedir: '/home'
Jul 13 20:37:40 bookworm cnid_metad[911]: getvolbypath: basedir regex: '/home', basedir match: "/home"
Jul 13 20:37:40 bookworm cnid_metad[911]: getvolbypath("/home/dmark/afp-data"): user: dmark, homedir: /home/dmark => realvolpath: "/home/dmark/afp-data"
Jul 13 20:37:40 bookworm cnid_metad[911]: creatvol(volume: 'dmark's home', path: "/home/dmark/afp-data", preset: '-'): BEGIN
Jul 13 20:37:40 bookworm cnid_metad[911]: initvol_vfs: enabling EA support with native EAs
Jul 13 20:37:40 bookworm cnid_metad[911]: uuid_bin2string{uuid}: mask: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
Jul 13 20:37:40 bookworm cnid_metad[911]: get_uuid('dmark's home'): generated UUID 'A4E1A5B5-43FE-ABC9-836A-B2186A8343E6'
Jul 13 20:37:40 bookworm cnid_metad[911]: Volume 'dmark's home': UUID 'A4E1A5B5-43FE-ABC9-836A-B2186A8343E6'
Jul 13 20:37:40 bookworm cnid_metad[911]: creatvol: END: 0
Jul 13 20:37:40 bookworm cnid_metad[911]: set_dbdir: volume: /home/dmark/afp-data, db path: /usr/local/var/netatalk/CNID//dmark's home/
Jul 13 20:37:40 bookworm cnid_metad[911]: maybe_start_dbd("/home/dmark/afp-data"): BEGIN
Jul 13 20:37:40 bookworm cnid_metad[911]: maybe_start_dbd: no cnid_dbd serving yet
Jul 13 20:37:40 bookworm cnid_metad[911]: unload_volumes: BEGIN
Jul 13 20:37:40 bookworm cnid_metad[911]: unload_volumes: END
Jul 13 20:37:40 bookworm cnid_dbd[917]: Set syslog logging to level: debug
Jul 13 20:37:40 bookworm cnid_dbd[917]: CNID Server: localhost:4700
Jul 13 20:37:40 bookworm cnid_dbd[917]: Global unix charset is UTF8
Jul 13 20:37:40 bookworm cnid_dbd[917]: Global vol charset is UTF8
Jul 13 20:37:40 bookworm cnid_dbd[917]: Global mac charset is MAC_ROMAN
Jul 13 20:37:40 bookworm cnid_dbd[917]: readextmap: loading "/usr/local/etc/extmap.conf"
Jul 13 20:37:40 bookworm cnid_dbd[917]: readextmap: done
Jul 13 20:37:40 bookworm cnid_dbd[917]: user: dmark, path /home/dmark/afp-data
Jul 13 20:37:40 bookworm cnid_dbd[917]: load_volumes: BEGIN
Jul 13 20:37:40 bookworm cnid_dbd[917]: load_volumes: no volumes yet
Jul 13 20:37:40 bookworm cnid_dbd[917]: load_volumes: loading: /usr/local/etc/afp.conf
Jul 13 20:37:40 bookworm cnid_dbd[917]: readvolfile: BEGIN
Jul 13 20:37:40 bookworm cnid_dbd[917]: readvolfile: sections: 2
Jul 13 20:37:40 bookworm cnid_dbd[917]: load_volumes: END
Jul 13 20:37:40 bookworm cnid_dbd[917]: getvolbypath("/home/dmark/afp-data")
Jul 13 20:37:40 bookworm cnid_dbd[917]: getvolbypath: user home section: 'Homes', basedir: '/home'
Jul 13 20:37:40 bookworm cnid_dbd[917]: getvolbypath: basedir regex: '/home', basedir match: "/home"
Jul 13 20:37:40 bookworm cnid_dbd[917]: getvolbypath("/home/dmark/afp-data"): user: dmark, homedir: /home/dmark => realvolpath: "/home/dmark/afp-data"
Jul 13 20:37:40 bookworm cnid_dbd[917]: creatvol(volume: 'dmark's home', path: "/home/dmark/afp-data", preset: '-'): BEGIN
Jul 13 20:37:40 bookworm cnid_dbd[917]: initvol_vfs: enabling EA support with native EAs
Jul 13 20:37:40 bookworm cnid_dbd[917]: uuid_bin2string{uuid}: mask: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
Jul 13 20:37:40 bookworm cnid_dbd[917]: get_uuid('dmark's home'): generated UUID '257C300E-B56E-7EC3-C246-89C3F15D3047'
Jul 13 20:37:40 bookworm cnid_dbd[917]: Volume 'dmark's home': UUID '257C300E-B56E-7EC3-C246-89C3F15D3047'
Jul 13 20:37:40 bookworm cnid_dbd[917]: creatvol: END: 0
Jul 13 20:37:40 bookworm cnid_dbd[917]: db dir: "/usr/local/var/netatalk/CNID//dmark's home//.AppleDB"
Jul 13 20:37:40 bookworm cnid_dbd[917]: Setting uid/gid to 0/0
Jul 13 20:37:40 bookworm cnid_dbd[917]: get_lock(LOCK_EXCL, "/usr/local/var/netatalk/CNID//dmark's home//.AppleDB")
Jul 13 20:37:40 bookworm cnid_dbd[917]: get_lock: got LOCK_EXCL lock
Jul 13 20:37:40 bookworm cnid_dbd[917]: Running recovery
Jul 13 20:37:40 bookworm cnid_dbd[917]: Finished recovery.
Jul 13 20:37:40 bookworm cnid_dbd[917]: Finished initializing BerkeleyDB environment
Jul 13 20:37:40 bookworm cnid_dbd[917]: See if we can upgrade the CNID database...
Jul 13 20:37:40 bookworm cnid_dbd[917]: Finished BerkeleyBD upgrade check
Jul 13 20:37:40 bookworm cnid_dbd[917]: CNID database version 1
Jul 13 20:37:40 bookworm cnid_dbd[917]: CNID database version 1
Jul 13 20:37:40 bookworm cnid_dbd[917]: Finished CNID database version upgrade check
Jul 13 20:37:40 bookworm cnid_dbd[917]: Finished opening BerkeleyDB databases
Jul 13 20:37:40 bookworm cnid_dbd[917]: Checkpoint interval: 1800 seconds. Next checkpoint: Jul 13 21:07:40.
Jul 13 20:37:40 bookworm afpd[913]: ipc_child_write(IPC_VOLUMES)
Jul 13 20:37:40 bookworm afpd[913]: ==> Finished AFP command: AFP_OPENVOL -> AFP_OK
Jul 13 20:37:40 bookworm afpd[913]: dsi_cmdreply(DSI ID: 552, len: 4): START
Jul 13 20:37:40 bookworm afpd[913]: dsi_cmdreply(DSI ID: 552, len: 4): END
Jul 13 20:37:40 bookworm afpd[913]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:40 bookworm afpd[913]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:40 bookworm afpd[910]: main: IPC request from child[913]
Jul 13 20:37:40 bookworm afpd[910]: ipc_server_read(IPC_VOLUMES): pid: 913
Jul 13 20:37:40 bookworm afpd[913]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:40 bookworm afpd[913]: dsi_stream_receive: DSI cmdlen: 28
Jul 13 20:37:40 bookworm afpd[913]: DSI request ID: 553
Jul 13 20:37:40 bookworm afpd[913]: <== Start AFP command: AFP_GETSESSTOKEN
Jul 13 20:37:40 bookworm afpd[913]: ipc_child_write(IPC_GETSESSION)
Jul 13 20:37:40 bookworm afpd[913]: ==> Finished AFP command: AFP_GETSESSTOKEN -> AFP_OK
Jul 13 20:37:40 bookworm afpd[913]: dsi_cmdreply(DSI ID: 553, len: 12): START
Jul 13 20:37:40 bookworm afpd[913]: dsi_cmdreply(DSI ID: 553, len: 12): END
Jul 13 20:37:40 bookworm afpd[913]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:40 bookworm afpd[913]: from_buf(read: 16, unread:58 , space left: 12582838): returning 16
Jul 13 20:37:40 bookworm afpd[913]: from_buf(read: 0, unread:0 , space left: 12582912): returning 58
Jul 13 20:37:40 bookworm afpd[913]: dsi_stream_receive: DSI cmdlen: 58
Jul 13 20:37:40 bookworm afpd[913]: DSI request ID: 554
Jul 13 20:37:40 bookworm afpd[913]: <== Start AFP command: AFP_EXCHANGEFILE
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 2): START
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 2): RESULT: pdid: 1, path: "/home/dmark/afp-data"
Jul 13 20:37:40 bookworm afpd[913]: movecwd(to: did: 2, "/home/dmark/afp-data")
Jul 13 20:37:40 bookworm afpd[913]: cname('/home/dmark/afp-data'): {file: 'Testing a word doc.docx'}
Jul 13 20:37:40 bookworm afpd[913]: cname('/home/dmark/afp-data') {end: curdir:'/home/dmark/afp-data', path:'Testing a word doc.docx'}
Jul 13 20:37:40 bookworm afpd[913]: absupath: /home/dmark/afp-data/Testing a word doc.docx
Jul 13 20:37:40 bookworm afpd[913]: file_access("Testing a word doc.docx"): mapped user mode: 0x86
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx", HF|O_RDWR): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx", HF|O_RDWR): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("Testing a word doc.docx"): opening base file for meta adouble EA
Jul 13 20:37:40 bookworm afpd[913]: ad_reso_size("Testing a word doc.docx"): BEGIN
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx", HF|O_RDWR): END: 0 [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx"): END: 0 {d: 0, m: 1, r: 0}[dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_lookup: CNID: 2, name: 'Testing a word doc.docx', inode: 0x1097af, type: 0 (0=file, 1=dir)
Jul 13 20:37:40 bookworm afpd[910]: main: IPC request from child[913]
Jul 13 20:37:40 bookworm afpd[910]: ipc_server_read(IPC_GETSESSION): pid: 913
Jul 13 20:37:40 bookworm afpd[910]: ipc_get_session(pid: 913, uid: 1000, time: 0x64b0c206)
Jul 13 20:37:40 bookworm afpd[910]: Setting client ID for 913
Jul 13 20:37:40 bookworm cnid_dbd[917]: dbd_lookup(DID:2/'Testing a word doc.docx',0x801/0x1097af): Got CNID: 1225
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_lookup: got CNID: 1225
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 1226): START
Jul 13 20:37:40 bookworm afpd[913]: dircache(cnid:1226): {not in cache}
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 1226): querying CNID database
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_resolve: resolving CNID: 1226
Jul 13 20:37:40 bookworm cnid_dbd[917]: dbd_resolve(CNID: 1226): did: 2, name: "Testing a word doc.docx.sb-aee4c48c-Bw9EqD"
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_resolve: resolved did: 2, name: 'Testing a word doc.docx.sb-aee4c48c-Bw9EqD'
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 1226): recursion for did: 2
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 2): START
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 2): RESULT: pdid: 1, path: "/home/dmark/afp-data"
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 1226): stating "/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD"
Jul 13 20:37:40 bookworm afpd[913]: dircache(did:1226,'Testing a word doc.docx.sb-aee4c48c-Bw9EqD'): {added}
Jul 13 20:37:40 bookworm afpd[913]: dirlookup(did: 1226): RESULT: pdid: 2, path: "/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD"
Jul 13 20:37:40 bookworm afpd[913]: movecwd(to: did: 1226, "/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD")
Jul 13 20:37:40 bookworm afpd[913]: cname('/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD'): {file: '.~WRD0005'}
Jul 13 20:37:40 bookworm afpd[913]: cname('/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD') {end: curdir:'/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD', path:'.~WRD0005'}
Jul 13 20:37:40 bookworm afpd[913]: file_access(".~WRD0005"): mapped user mode: 0x86
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005", HF|O_RDWR): BEGIN {d: 0, m: 0, r: 0}[dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005", HF|O_RDWR): BEGIN [dfd: -1 (ref: 0), mfd: -1 (ref: 0), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea(".~WRD0005"): opening base file for meta adouble EA
Jul 13 20:37:40 bookworm afpd[913]: ad_reso_size(".~WRD0005"): BEGIN
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005", HF|O_RDWR): END: 0 [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005"): END: 0 {d: 0, m: 1, r: 0}[dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_lookup: CNID: 1226, name: '.~WRD0005', inode: 0x26a, type: 0 (0=file, 1=dir)
Jul 13 20:37:40 bookworm cnid_dbd[917]: dbd_lookup(DID:1226/'.~WRD0005',0x801/0x26a): Got CNID: 1227
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_lookup: got CNID: 1227
Jul 13 20:37:40 bookworm afpd[913]: renamefile: src[-1, "/home/dmark/afp-data/Testing a word doc.docx"] -> dst[".AppleTemp6shwtw"]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.AppleTemp6shwtw", HF|O_RDWR): BEGIN {d: 0, m: 1, r: 0}[dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.AppleTemp6shwtw", HF|O_RDWR): BEGIN [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_reso_size(".AppleTemp6shwtw"): BEGIN
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.AppleTemp6shwtw", HF|O_RDWR): END: 0 [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.AppleTemp6shwtw"): END: 0 {d: 0, m: 2, r: 0}[dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_flush(HF|O_RDWR)
Jul 13 20:37:40 bookworm afpd[913]: ad_flush_hf(HF|O_RDWR)
Jul 13 20:37:40 bookworm afpd[913]: ad_rebuild_adouble_header_ea
Jul 13 20:37:40 bookworm afpd[913]: ad_close(HF): BEGIN: {d: 0, m: 2, r: 0} [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_close(HF): END: 0 {d: 0, m: 1, r: 0} [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: renamefile: src[-1, ".~WRD0005"] -> dst["/home/dmark/afp-data/Testing a word doc.docx"]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx", HF|O_RDWR): BEGIN {d: 0, m: 1, r: 0}[dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx", HF|O_RDWR): BEGIN [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_reso_size("/home/dmark/afp-data/Testing a word doc.docx"): BEGIN
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx", HF|O_RDWR): END: 0 [dfd: 9 (ref: 2), mfd: 9 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx"): END: 0 {d: 0, m: 2, r: 0}[dfd: 9 (ref: 2), mfd: 9 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_flush(HF|O_RDWR)
Jul 13 20:37:40 bookworm afpd[913]: ad_flush_hf(HF|O_RDWR)
Jul 13 20:37:40 bookworm afpd[913]: ad_rebuild_adouble_header_ea
Jul 13 20:37:40 bookworm afpd[913]: ad_close(HF): BEGIN: {d: 0, m: 2, r: 0} [dfd: 9 (ref: 2), mfd: 9 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_close(HF): END: 0 {d: 0, m: 1, r: 0} [dfd: 9 (ref: 1), mfd: 9 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: renamefile: src[-1, ".AppleTemp6shwtw"] -> dst[".~WRD0005"]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005", HF|O_RDWR): BEGIN {d: 0, m: 1, r: 0}[dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005", HF|O_RDWR): BEGIN [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_reso_size(".~WRD0005"): BEGIN
Jul 13 20:37:40 bookworm afpd[913]: ad_open_hf_ea("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005", HF|O_RDWR): END: 0 [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_open("/home/dmark/afp-data/Testing a word doc.docx.sb-aee4c48c-Bw9EqD/.~WRD0005"): END: 0 {d: 0, m: 2, r: 0}[dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_flush(HF|O_RDWR)
Jul 13 20:37:40 bookworm afpd[913]: ad_flush_hf(HF|O_RDWR)
Jul 13 20:37:40 bookworm afpd[913]: ad_rebuild_adouble_header_ea
Jul 13 20:37:40 bookworm afpd[913]: ad_close(HF): BEGIN: {d: 0, m: 2, r: 0} [dfd: 5 (ref: 2), mfd: 5 (ref: 2), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: ad_close(HF): END: 0 {d: 0, m: 1, r: 0} [dfd: 5 (ref: 1), mfd: 5 (ref: 1), rfd: -1 (ref: 0)]
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_delete: delete CNID: 1225
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: CNID 1225 deleted
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_delete: deleted CNID: 1225
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_delete: delete CNID: 1227
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: CNID 1227 deleted
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_delete: deleted CNID: 1227
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_update: CNID: 1227, name: '.~WRD0005', inode: 0x1097af, type: 0 (0=file, 1=dir)
Jul 13 20:37:40 bookworm cnid_dbd[917]: key not found
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: CNID 1227 not in database
Jul 13 20:37:40 bookworm cnid_dbd[917]: key not found
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: dev/ino: 0x801/0x1097af not in database
Jul 13 20:37:40 bookworm cnid_dbd[917]: key not found
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: DID: 1226, name: .~WRD0005 not in database
Jul 13 20:37:40 bookworm cnid_dbd[917]: dbd_update: Updated dbd with dev/ino: 0x801/0x1097af, did: 1226, name: .~WRD0005, cnid: 1227
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_update: updated
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_update: CNID: 1225, name: 'Testing a word doc.docx', inode: 0x26a, type: 0 (0=file, 1=dir)
Jul 13 20:37:40 bookworm cnid_dbd[917]: key not found
Jul 13 20:37:40 bookworm systemd[1]: session-c35.scope: Deactivated successfully.
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: CNID 1225 not in database
Jul 13 20:37:40 bookworm systemd-logind[340]: Session c35 logged out. Waiting for processes to exit.
Jul 13 20:37:40 bookworm cnid_dbd[917]: key not found
Jul 13 20:37:40 bookworm systemd-logind[340]: Removed session c35.
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: dev/ino: 0x801/0x26a not in database
Jul 13 20:37:40 bookworm cnid_dbd[917]: key not found
Jul 13 20:37:40 bookworm cnid_dbd[917]: cnid_delete: DID: 2, name: Testing a word doc.docx not in database
Jul 13 20:37:40 bookworm cnid_dbd[917]: dbd_update: Updated dbd with dev/ino: 0x801/0x26a, did: 2, name: Testing a word doc.docx, cnid: 1225
Jul 13 20:37:40 bookworm afpd[913]: cnid_dbd_update: updated
Jul 13 20:37:40 bookworm afpd[913]: ad_entry(): invalid size 16 bytes
Jul 13 20:37:40 bookworm afpd[913]: ===============================================================
Jul 13 20:37:40 bookworm afpd[913]: INTERNAL ERROR: Signal 11 in pid 913 (3.1.99dev)
Jul 13 20:37:40 bookworm afpd[913]: ===============================================================
Jul 13 20:37:40 bookworm afpd[913]: PANIC: internal error
Jul 13 20:37:40 bookworm afpd[913]: BACKTRACE: 11 stack frames:
Jul 13 20:37:40 bookworm afpd[913]:  #0 /usr/local/lib/libatalk.so.0(netatalk_panic+0x22) [0x7ff38aa9f932]
Jul 13 20:37:40 bookworm afpd[913]:  #1 /usr/local/lib/libatalk.so.0(+0x2ba6a) [0x7ff38aa9fa6a]
Jul 13 20:37:40 bookworm afpd[913]:  #2 /lib/x86_64-linux-gnu/libc.so.6(+0x3bf90) [0x7ff38a47ff90]
Jul 13 20:37:40 bookworm afpd[913]:  #3 /lib/x86_64-linux-gnu/libc.so.6(+0x16e3d7) [0x7ff38a5b23d7]
Jul 13 20:37:40 bookworm afpd[913]:  #4 /usr/local/lib/libatalk.so.0(ad_copy_header+0x4d) [0x7ff38aa840cd]
Jul 13 20:37:40 bookworm afpd[913]:  #5 /usr/local/sbin/afpd(afp_exchangefiles+0x72a) [0x560b5493c02a]
Jul 13 20:37:40 bookworm afpd[913]:  #6 /usr/local/sbin/afpd(afp_over_dsi+0x562) [0x560b54926fd2]
Jul 13 20:37:40 bookworm afpd[913]:  #7 /usr/local/sbin/afpd(main+0x97f) [0x560b5492507f]
Jul 13 20:37:40 bookworm afpd[913]:  #8 /lib/x86_64-linux-gnu/libc.so.6(+0x2718a) [0x7ff38a46b18a]
Jul 13 20:37:40 bookworm afpd[913]:  #9 /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85) [0x7ff38a46b245]
Jul 13 20:37:40 bookworm afpd[913]:  #10 /usr/local/sbin/afpd(_start+0x21) [0x560b549253c1]
Jul 13 20:37:40 bookworm afpd[910]: child[913]: killed by signal 6
Jul 13 20:37:41 bookworm afpd[910]: main: IPC request from child[918]
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: AFP/TCP session from 10.0.0.50:55436
Jul 13 20:37:41 bookworm afpd[918]: unload_volumes: BEGIN
Jul 13 20:37:41 bookworm afpd[918]: unload_volumes: END
Jul 13 20:37:41 bookworm afpd[918]: dircache_init: done. max dircache size: 8192
Jul 13 20:37:41 bookworm afpd[918]: ipc_child_write(IPC_STATE)
Jul 13 20:37:41 bookworm afpd[910]: main: IPC request from child[918]
Jul 13 20:37:41 bookworm afpd[910]: ipc_server_read(IPC_STATE): pid: 918
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: dsi_stream_receive: DSI cmdlen: 28
Jul 13 20:37:41 bookworm afpd[918]: DSI request ID: 556
Jul 13 20:37:41 bookworm afpd[918]: <== Start AFP command: AFP_LOGIN_EXT
Jul 13 20:37:41 bookworm afpd[918]: DHX2 login: dmark
Jul 13 20:37:41 bookworm afpd[918]: ==> Finished AFP command: AFP_LOGIN_EXT -> AFPERR_AUTHCONT
Jul 13 20:37:41 bookworm afpd[918]: dsi_cmdreply(DSI ID: 556, len: 264): START
Jul 13 20:37:41 bookworm afpd[918]: dsi_cmdreply(DSI ID: 556, len: 264): END
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: dsi_stream_receive: DSI cmdlen: 148
Jul 13 20:37:41 bookworm afpd[918]: DSI request ID: 557
Jul 13 20:37:41 bookworm afpd[918]: <== Start AFP command: AFP_LOGINCONT
Jul 13 20:37:41 bookworm afpd[918]: ==> Finished AFP command: AFP_LOGINCONT -> AFPERR_AUTHCONT
Jul 13 20:37:41 bookworm afpd[918]: dsi_cmdreply(DSI ID: 557, len: 34): START
Jul 13 20:37:41 bookworm afpd[918]: dsi_cmdreply(DSI ID: 557, len: 34): END
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0
Jul 13 20:37:41 bookworm afpd[918]: from_buf(read: 0, unread:0 , space left: 12582912): returning 0

@slowfranklin
Copy link
Member

slowfranklin commented Jul 30, 2023 via email

@rdmark
Copy link
Member

rdmark commented Jul 31, 2023

@slowfranklin The difference in your setup might be the file system. I replicated your setup but on my ext4 file system, and observing the behavior illustrated in the screenshot here. Word creates a zero byte bundle on the Netatalk volume, but then hangs permanently. Shortly after you can see the temporary folder appearing in the shared Netatalk volume.

Screenshot 2023-07-30 at 10 40 25 PM

@slowfranklin
Copy link
Member

slowfranklin commented Jul 31, 2023 via email

@ITelligencia
Copy link
Author

ITelligencia commented Jul 31, 2023 via email

@dpm3354
Copy link

dpm3354 commented Jul 31, 2023

These files @rdmark showed were orphaned on my system too. From what I can tell, these files were created, MS Word froze and then the files were left there. My fs was also ext4.

@apparentorder
Copy link

apparentorder commented Aug 5, 2023

I have a similar issue with 3.1.15 on FreeBSD 13.2 and a ZFS-backed share.

With ZFS xattr=on (default) it triggers the segfault immediately when accessing the share from macOS.
When setting xattr=off for the zfs data set, it works fine.

Hope this additional data point helps.

@rdmark
Copy link
Member

rdmark commented Aug 8, 2023

With some additional logging I tracked down the failing assertion to this line: https://github.com/Netatalk/netatalk/blob/96f4fa3355c470ae6763327a2d270f400f75c210/libatalk/adouble/ad_open.c#L1660C10-L1660C10

It seems this host of headers are failing the overflow check since the buffer is 0 bytes. Looking at the callstack this comes from when Word's temp files are being copied.

Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 354 required_len 16 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 122 required_len 32 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 370 required_len 4 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 374 required_len 8 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 382 required_len 8 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 390 required_len 8 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 398 required_len 4 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 354 required_len 16 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 122 required_len 32 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 370 required_len 4 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 374 required_len 8 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 382 required_len 8 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 390 required_len 8 bufsize 0
Aug 08 05:06:11 buntu afpd[157327]: ad_entry_check_size(): overflow off 398 required_len 4 bufsize 0

Next, to figure out why we have 0 buffer here...

@rdmark
Copy link
Member

rdmark commented Aug 10, 2023

I have a tentative fix in PR #363 -- any takers to run a few tests?

The nature of this fix is that when copying metadata, we now check that the destination has > 0 buffer before attempting the copy. The fix may have side effects, so please be careful to backup your data before testing!

@rdmark rdmark self-assigned this Aug 10, 2023
@ITelligencia
Copy link
Author

ITelligencia commented Aug 10, 2023 via email

@rdmark
Copy link
Member

rdmark commented Aug 10, 2023

@ITelligencia Correct, please clone this git repo, then checkout the rdmark-issue-236 branch.

@rdmark
Copy link
Member

rdmark commented Aug 10, 2023

For the record, doing some git blaming I found an adjacent bug that was fixed 10 years ago: https://sourceforge.net/p/netatalk/bugs/510/

Here I learned that the apple_dump tool actually supports EA metadata, i.e. apple_dump -e /path/to/file. This is handy for inspecting offending headers. (Requires the attribute tools being installed, e.g. the attr deb package on Debian).

@ITelligencia
Copy link
Author

ITelligencia commented Aug 11, 2023 via email

@rdmark
Copy link
Member

rdmark commented Aug 11, 2023

@ITelligencia May I ask you to share the exact netatalk code revision that you used for testing? E.g. do git log and tell me the HEAD commit.

The reason for asking, is because I did a major rebase of my work branch with #178 last night, while reverting my own crude fix. So depending on when you did git pull you may have very different code.

@ITelligencia
Copy link
Author

ITelligencia commented Aug 11, 2023 via email

@rdmark
Copy link
Member

rdmark commented Aug 11, 2023

@ITelligencia Thanks, so you're definitely using outdated code there. May I ask you to pull the latest code and run your tests again (make sure you rebase with git pull --rebase)? Please make sure to re-enable xattr on the file system.

@ITelligencia
Copy link
Author

ITelligencia commented Aug 11, 2023 via email

@rdmark
Copy link
Member

rdmark commented Aug 11, 2023

Excellent news -- thank you so much for running these tests!

@rdmark
Copy link
Member

rdmark commented Aug 11, 2023

The primary bug fix #178 has been merged to main, so I'm closing this ticket as resolved. Please raise a new ticket if you run into similar assertions down the line!

@rdmark rdmark closed this as completed Aug 11, 2023
@rdmark
Copy link
Member

rdmark commented Aug 14, 2023

The Debian Buster netatalk package has been hotfixed now, so if you're running Buster you can do apt update && apt upgrade to get the fixed binary.

The patch will probably propagate to Ubuntu soon, too, although I don't have any insights into their process.

@rdmark
Copy link
Member

rdmark commented Aug 31, 2023

Note that the netatalk package in Debian unstable has been patched now with a fix for this bug:

$ apt show netatalk
Package: netatalk
Version: 3.1.15~ds-3

@rdmark rdmark added this to 3.1.16 Sep 3, 2023
@rdmark rdmark moved this to Done in 3.1.16 Sep 3, 2023
@dpm3354
Copy link

dpm3354 commented Nov 22, 2023

I have time to install and try this patch over the next two to four weeks. I am unfamiliar with the ubuntu/deb patch/release process. It appears this is not yet in ubuntu, is that correct? Otherwise, please point me to the correct version for ubuntu and I will be happy to provide feedback on if this is working for me.

@rdmark
Copy link
Member

rdmark commented Nov 24, 2023

@dpm3354 Yes you're correct, Ubuntu hasn't updated their package since 3.1.15~ds-1ubuntu1, whereas in upstream Debian we put out a 3.1.18 deb two months ago.

Ubuntu's deb sync process is documented here https://wiki.ubuntu.com/SyncRequestProcess

Edit: It seems like anyone can initiate a out-of-cycle sync request by filing a Launchpad ticket. You could try it yourself if you feel up for it. :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
No open projects
Status: Done
Development

No branches or pull requests

5 participants