FreeBSD with Netatalk3ではまる

気付いたらnetatalk2.2が何故か止まっており、各種デーモンを再起動してやっても動かない。再起動してやってもコアを吐く。
何もやってないのに動かなくなった……という言葉があるが、文字通りメンテすら放置してたストレージサーバ(NFS+samba+netatalk)である。
心当たりがない。
設定ファイルを見直すが、おかしなことはないし、ログを見ても原因分からずというところだった。

ので

9月頭にportsに降ってきたnetatalk3系を試すのだ。

設定。

※まだ動いてません。以下は参考程度にね

/etc/rc.conf
# netatalk
dbus_enable="YES"
avahi_daemon_enable="YES"
avahi_dnsconfd_enable="YES"
afpd_enable="YES"
netatalk_enable="YES"
/usr/local/etc/afp.conf

3系から一つの設定ファイルにまとまった。
とても分かりやすい。

[Global]
  uam list = uams_dhx2_passwd.so
  log file = /var/log/netatalk.log
  ;log level = default:info
  log level = default:debug
  vol preset = default_preset

[default_preset]
  file perm = 0600
  directory perm = 0700

[Homes]
basedir regex = /home

[share]
 path = /netatalk

起動

# /usr/local/etc/rc.d/dbus start                                                                                                                    
# /usr/local/etc/rc.d/avahi-daemon start
# /usr/local/etc/rc.d/avahi-dnsconfd start
# afpd -d -F /usr/local/etc/afp.conf

起動したら、/var/log/netatalk.logをヲチする。

$ tail -f /var/log/netatalk.log

接続確認。

Netatalkのバージョンを調べる方法」に紹介されている、asip-status.plをダウンロード。
デフォだと動かんので、とりあえず45行目の"print "This edition is a part of Netatalk @NETATALK_VERSION@\n";"をコメントアウト
ローカルで動かすとこんな感じ(Macでも動きますよ)。

$ ./asip-status.pl localhost
AFP reply from localhost:548
Flags: 1 Cmd: 3 ID: 57005
Reply: DSIGetStatus
Request ID: 57005
Machine type: Netatalk3.0
AFP versions: AFP2.2,AFPX03,AFP3.1,AFP3.2,AFP3.3
UAMs: DHX2
Volume Icon & Mask: Yes
Flags: SupportsCopyFile,SupportsServerMessages,SupportsServerSignature,SupportsTCP/IP,SupportsSrvrNotifications,SupportsOpenDirectory,SupportsUTF8Servername,SupportsUUIDs,SupportsSuperClient
Server name: menma
Signature:
8f 80 9e d6 5d da 82 77 aa 4b 1c a5 d5 00 c7 0a ....]..w.K......

Network address: 192.168.1

認証もDHX2になっていて、問題ない……ように見える。

ここで、Finderから接続してみようと試みる。

悲しい。

原因究明を試みる(志半ばで倒れる)

サーバサイドのログを見よう

(長いので一番最後に貼り付けます)
認証は問題無く行われている。クライアントの側から切断処理を行っている。

クライアントからみてみよう

GUIは詳細なエラーが出ないので、mountコマンド直叩きすればええんや!

[m-bird@macbook ~]% mount_afp afp://m-bird:PASSWORD@menma/home/dorio /Volumes/mnt/
mount_afp: AFPMountURL returned error -5019, errno is 2
[m-bird@macbook ~]% mount_afp afp://m-bird:PASSWORD@menma.home/netatalk /Volumes/mnt/
mount_afp: AFPMountURL returned error -5019, errno is 2

とてもユーザフレンドリーなエラーメッセージである。
AFP の mount でのエラーーーBalun Software (Info)」を参考に、エラー番号からの内容を確認する。"errno 2 = ENOENT (No such file or directory)"とのことである。
ぼくにはそのディレクトリがあるように見える。よく分からない。

というわけで

一日かけてもファイルサーバにアクセスできないので泣きたいです。

以下にログを貼り付けます。

# 接続時
Sep 26 02:32:46.477937 afpd[47571] {socket.c:445} (D5:Default): fdset_add_fd: adding fd 8 in slot 1
Sep 26 02:32:46.477984 afpd[47571] {main.c:434} (D5:AFPDaemon): main: IPC request from child[47586]
Sep 26 02:32:46.478391 afpd[47571] {socket.c:445} (D5:Default): fdset_add_fd: adding fd 9 in slot 2
Sep 26 02:32:46.478471 afpd[47571] {main.c:434} (D5:AFPDaemon): main: IPC request from child[47586]
Sep 26 02:32:46.478626 afpd[47587] {dsi_tcp.c:199} (I:DSI): AFP/TCP session from 192.168.128.139:61575
Sep 26 02:32:46.478701 afpd[47571] {main.c:179} (I:AFPDaemon): child[47586]: exited 1
Sep 26 02:32:46.479216 afpd[47571] {main.c:434} (D5:AFPDaemon): main: IPC request from child[47587]
Sep 26 02:32:46.479383 afpd[47571] {main.c:181} (I:AFPDaemon): child[47587]: done
Sep 26 02:32:46.493947 afpd[47571] {socket.c:445} (D5:Default): fdset_add_fd: adding fd 8 in slot 1
Sep 26 02:32:46.493989 afpd[47571] {main.c:434} (D5:AFPDaemon): main: IPC request from child[47588]
Sep 26 02:32:46.494039 afpd[47588] {dsi_tcp.c:199} (I:DSI): AFP/TCP session from 192.168.128.139:61576
Sep 26 02:32:46.494116 afpd[47588] {netatalk_conf.c:1198} (D5:AFPDaemon): unload_volumes: BEGIN
Sep 26 02:32:46.494135 afpd[47588] {netatalk_conf.c:1077} (D5:AFPDaemon): volume_free('share'): BEGIN
Sep 26 02:32:46.494160 afpd[47588] {netatalk_conf.c:1096} (D5:AFPDaemon): volume_free: END
Sep 26 02:32:46.494175 afpd[47588] {netatalk_conf.c:1205} (D5:AFPDaemon): unload_volumes: END
Sep 26 02:32:46.494218 afpd[47588] {dircache.c:576} (D5:AFPDaemon): dircache_init: done. max dircache size: 8192
Sep 26 02:32:46.494252 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:46.494264 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:46.494523 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:46.494540 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 28
Sep 26 02:32:46.494550 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 2
Sep 26 02:32:46.494561 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_LOGIN_EXT
Sep 26 02:32:46.494796 afpd[47588] {uams_dhx2_passwd.c:263} (I:UAMS): DHX2 login: m-bird

#---一瞬ここでログの流れが止まり、再び時が動き出す

Sep 26 02:32:47.797275 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_LOGIN_EXT -> AFPERR_AUTHCONT
Sep 26 02:32:47.797293 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 2, len: 264): START
Sep 26 02:32:47.797326 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 2, len: 264): END
Sep 26 02:32:47.797349 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.797364 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.814143 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.814162 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 148
Sep 26 02:32:47.814172 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 3
Sep 26 02:32:47.814183 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_LOGINCONT
Sep 26 02:32:47.822734 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_LOGINCONT -> AFPERR_AUTHCONT
Sep 26 02:32:47.822746 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 3, len: 34): START
Sep 26 02:32:47.822765 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 3, len: 34): END
Sep 26 02:32:47.822777 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.822789 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.823666 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.823681 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 276
Sep 26 02:32:47.823691 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 4
Sep 26 02:32:47.823701 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_LOGINCONT
Sep 26 02:32:47.824202 afpd[47588] {auth.c:242} (N:AFPDaemon): AFP3.3 Login by m-bird
Sep 26 02:32:47.824369 afpd[47588] {auth.c:272} (D5:AFPDaemon): obj->options.admingid == 0
Sep 26 02:32:47.824398 afpd[47588] {auth.c:328} (D5:AFPDaemon): login: supplementary groups:  1001 0
Sep 26 02:32:47.824423 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_LOGINCONT -> AFP_OK
Sep 26 02:32:47.824434 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 4, len: 0): START
Sep 26 02:32:47.824462 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 4, len: 0): END
Sep 26 02:32:47.824475 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.824486 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.824779 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.824795 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 8
Sep 26 02:32:47.824805 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 5
Sep 26 02:32:47.824815 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_GETUSERINFO
Sep 26 02:32:47.824825 afpd[47588] {auth.c:948} (D5:AFPDaemon): begin afp_getuserinfo:
Sep 26 02:32:47.824835 afpd[47588] {auth.c:1008} (D5:AFPDaemon): END afp_getuserinfo:
Sep 26 02:32:47.824845 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_GETUSERINFO -> AFP_OK
Sep 26 02:32:47.824855 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 5, len: 6): START
Sep 26 02:32:47.824872 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 5, len: 6): END
Sep 26 02:32:47.824910 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.824948 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.825248 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.825293 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 2
Sep 26 02:32:47.825314 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 6
Sep 26 02:32:47.825330 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_GETSRVPARAM
Sep 26 02:32:47.825353 afpd[47588] {netatalk_conf.c:1134} (D5:AFPDaemon): load_volumes: BEGIN
Sep 26 02:32:47.825369 afpd[47588] {netatalk_conf.c:1144} (D5:AFPDaemon): load_volumes: no volumes yet
Sep 26 02:32:47.825522 afpd[47588] {netatalk_conf.c:1172} (D5:AFPDaemon): load_volumes: loading: /usr/local/etc/afp.conf
Sep 26 02:32:47.825630 afpd[47588] {netatalk_conf.c:963} (D5:AFPDaemon): readvolfile: BEGIN
Sep 26 02:32:47.825647 afpd[47588] {netatalk_conf.c:966} (D5:AFPDaemon): readvolfile: sections: 4
Sep 26 02:32:47.825658 afpd[47588] {netatalk_conf.c:970} (D5:AFPDaemon): readvolfile: default_preset: default_preset
Sep 26 02:32:47.825671 afpd[47588] {netatalk_conf.c:993} (D5:AFPDaemon): readvolfile: basedir regex: '/home'
Sep 26 02:32:47.825738 afpd[47588] {netatalk_conf.c:574} (D5:AFPDaemon): createvol(volume: 'm-bird's home', path: "/home/m-bird/", preset: 'default_preset'): BEGIN
Sep 26 02:32:47.825827 afpd[47588] {netatalk_conf.c:255} (D5:AFPDaemon): Volume "/home/m-bird/" ACL support: no
Sep 26 02:32:47.825838 afpd[47588] {netatalk_conf.c:883} (D5:AFPDaemon): creatvol("/home/m-bird/"): disabling ACL support
Sep 26 02:32:47.825921 afpd[47588] {vfs.c:888} (D5:AFPDaemon): initvol_vfs: enabling EA support with native EAs
Sep 26 02:32:47.825934 afpd[47588] {netatalk_conf.c:912} (D5:AFPDaemon): createvol: END: 0
Sep 26 02:32:47.825947 afpd[47588] {netatalk_conf.c:574} (D5:AFPDaemon): createvol(volume: 'share', path: "/netatalk", preset: 'default_preset'): BEGIN
Sep 26 02:32:47.826009 afpd[47588] {netatalk_conf.c:255} (D5:AFPDaemon): Volume "/netatalk" ACL support: no
Sep 26 02:32:47.826021 afpd[47588] {netatalk_conf.c:883} (D5:AFPDaemon): creatvol("/netatalk"): disabling ACL support
Sep 26 02:32:47.826104 afpd[47588] {vfs.c:888} (D5:AFPDaemon): initvol_vfs: enabling EA support with native EAs
Sep 26 02:32:47.826116 afpd[47588] {netatalk_conf.c:912} (D5:AFPDaemon): createvol: END: 0
Sep 26 02:32:47.826171 afpd[47588] {netatalk_conf.c:1190} (D5:AFPDaemon): load_volumes: END
Sep 26 02:32:47.826243 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_GETSRVPARAM -> AFP_OK
Sep 26 02:32:47.826265 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 6, len: 26): START
Sep 26 02:32:47.826293 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 6, len: 26): END
Sep 26 02:32:47.826313 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.826332 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.827290 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.827306 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 10
Sep 26 02:32:47.827316 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 7
Sep 26 02:32:47.827326 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_OPENVOL
Sep 26 02:32:47.827340 afpd[47588] {netatalk_conf.c:1134} (D5:AFPDaemon): load_volumes: BEGIN
Sep 26 02:32:47.827373 afpd[47588] {netatalk_conf.c:1190} (D5:AFPDaemon): load_volumes: END
Sep 26 02:32:47.827387 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_OPENVOL -> AFPERR_PARAM
Sep 26 02:32:47.827413 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 7, len: 0): START
Sep 26 02:32:47.827443 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 7, len: 0): END
Sep 26 02:32:47.827462 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.827477 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.827917 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.827933 afpd[47588] {dsi_stream.c:601} (D5:DSI): dsi_stream_receive: DSI cmdlen: 2
Sep 26 02:32:47.827943 afpd[47588] {afp_dsi.c:604} (D5:DSI): DSI request ID: 8
Sep 26 02:32:47.827953 afpd[47588] {afp_dsi.c:619} (D5:AFPDaemon): <== Start AFP command: AFP_LOGOUT
Sep 26 02:32:47.827963 afpd[47588] {auth.c:856} (N:AFPDaemon): AFP logout by m-bird
Sep 26 02:32:47.827974 afpd[47588] {afp_dsi.c:626} (D5:AFPDaemon): ==> Finished AFP command: AFP_LOGOUT -> AFP_OK
Sep 26 02:32:47.827984 afpd[47588] {dsi_cmdreply.c:24} (D5:DSI): dsi_cmdreply(DSI ID: 8, len: 0): START
Sep 26 02:32:47.828001 afpd[47588] {dsi_cmdreply.c:33} (D5:DSI): dsi_cmdreply(DSI ID: 8, len: 0): END
Sep 26 02:32:47.828013 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.828024 afpd[47588] {dsi_stream.c:162} (D5:DSI): from_buf(read: 0, unread:0 , space left: 3646080): returning 0
Sep 26 02:32:47.828384 afpd[47588] {dsi_stream.c:479} (E:DSI): dsi_stream_read: len:0, unexpected EOF
Sep 26 02:32:47.828397 afpd[47588] {afp_dsi.c:507} (N:AFPDaemon): afp_over_dsi: client logged out, terminating DSI session
Sep 26 02:32:47.828418 afpd[47571] {main.c:434} (D5:AFPDaemon): main: IPC request from child[47588]
Sep 26 02:32:47.828424 afpd[47588] {afp_dsi.c:105} (N:AFPDaemon): AFP statistics: 0.59 KB read, 0.46 KB written
Sep 26 02:32:47.828454 afpd[47588] {dircache.c:616} (I:AFPDaemon): dircache statistics: entries: 0, lookups: 0, hits: 0, misses: 0, added: 0, removed: 0, expunged: 0, evicted: 0
Sep 26 02:32:47.828886 afpd[47571] {main.c:181} (I:AFPDaemon): child[47588]: done