家鯖をFreeBSD 11.0-RELEASEに上げたタイミングで、Netatalk 3.1.8に更新したのだが、どうにもBonjourで広告されなさげ。OS更新で諸々おかしくなったか？と思い、NetatalkやmDNSResponderを再ビルドしても症状変わらず。

afpd -Vしてみたら、なんとZeroconfがAvahiになってた。間違いなくmDNSResponderを選んでるんだけどな…。

$ afpd -V
afpd 3.1.8 - Apple Filing Protocol (AFP) daemon of Netatalk
 
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
Foundation; either version 2 of the License, or (at your option) any later
version. Please see the file COPYING for further information and details.
 
afpd has been compiled with support for these features:
 
          AFP versions:	2.2 3.0 3.1 3.2 3.3 3.4 
         CNID backends:	dbd last tdb 
      Zeroconf support:	Avahi
  TCP wrappers support:	Yes
         Quota support:	No
   Admin group support:	Yes
    Valid shell checks:	Yes
      cracklib support:	No
            EA support:	ad | sys
           ACL support:	Yes
          LDAP support:	No
         D-Bus support:	Yes
     Spotlight support:	No
         DTrace probes:	No
 
              afp.conf:	/usr/local/etc/afp.conf
           extmap.conf:	/usr/local/etc/extmap.conf
       state directory:	/var/netatalk/
    afp_signature.conf:	/var/netatalk/afp_signature.conf
      afp_voluuid.conf:	/var/netatalk/afp_voluuid.conf
       UAM search path:	/usr/local/libexec/netatalk-uams//
  Server messages path:	/var/netatalk/msg/

portsの更新ログ見ると、10/10に「Fix build with mDNSResponder」とあったので、portsがバグってたっぽい。と、ここで、11-RELEASEにした際Portsツリーを更新してなかったことに気付く。

portsnap fetch extractしてportmaster netatalk3したところ、無事mDNSResponderで広告されるようになった。

$ afpd -V
afpd 3.1.10 - Apple Filing Protocol (AFP) daemon of Netatalk
 
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
Foundation; either version 2 of the License, or (at your option) any later
version. Please see the file COPYING for further information and details.
 
afpd has been compiled with support for these features:
 
          AFP versions:	2.2 3.0 3.1 3.2 3.3 3.4 
         CNID backends:	dbd last tdb 
      Zeroconf support:	mDNSResponder
  TCP wrappers support:	Yes
         Quota support:	No
   Admin group support:	Yes
    Valid shell checks:	Yes
      cracklib support:	No
            EA support:	ad | sys
           ACL support:	Yes
          LDAP support:	No
         D-Bus support:	Yes
     Spotlight support:	No
         DTrace probes:	No
 
              afp.conf:	/usr/local/etc/afp.conf
           extmap.conf:	/usr/local/etc/extmap.conf
       state directory:	/var/netatalk/
    afp_signature.conf:	/var/netatalk/afp_signature.conf
      afp_voluuid.conf:	/var/netatalk/afp_voluuid.conf
       UAM search path:	/usr/local/libexec/netatalk-uams//
  Server messages path:	/var/netatalk/msg/

3.1.7では問題なかったので、もしかして最近までずっとバグってた系・・・？

いつ頃からから、Netatalk 3.1.7で提供しているボリュームとの接続が突然切れる現象が起きるようになった。

正確な発症条件は不明だが、ストレージの読み書き負荷が高い時や、巨大な動画ファイルでシークすると発生しやすい印象。いずれにせよ、何の前触れもなく発生し接続断のダイアログも出ないので地味にストレスが溜まる。

接続が切れる直前は決まって、ログにdsi_stream_sendかafp_read_extのCannot allocate memoryが記録されている。

Jun 02 23:55:18.897112 afpd[57517] {afp_dsi.c:624} (debug:AFPDaemon): <== Start AFP command: AFP_READ_EXT
Jun 02 23:55:18.897126 afpd[57517] {fork.c:829} (debug:AFPDaemon): afp_read(fork: 422 [data], off: 1310720, len: 65536, size: 2222591)
Jun 02 23:55:18.897156 afpd[57517] {fork.c:880} (debug:AFPDaemon): afp_read(name: "01 プロローグ・静かなる侵略.m4a", offset: 1310720, reqcount: 65536): got 65536 bytes from file
Jun 02 23:55:18.897170 afpd[57517] {dsi_read.c:29} (maxdebug:DSI): dsi_readinit: sending 65536 bytes from buffer, total size: 65536
Jun 02 23:55:18.897183 afpd[57517] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(65536 bytes): START
Jun 02 23:55:18.897353 afpd[57517] {dsi_stream.c:564} (error:DSI): dsi_stream_send: Cannot allocate memory
Jun 02 23:55:18.897375 afpd[57517] {fork.c:913} (error:AFPDaemon): afp_read(01 プロローグ・静かなる侵略.m4a): Cannot allocate memory
Jun 02 23:55:18.897397 afpd[57517] {dsi_stream.c:281} (maxdebug:DSI): dsi_stream_write(send: 18 bytes): START
Jun 02 23:55:18.897419 afpd[57517] {dsi_stream.c:325} (maxdebug:DSI): dsi_stream_write(send: 18 bytes): END
（中略）
Jun 02 23:55:18.898533 afpd[57517] {cnid_dbd.c:498} (debug:CNID): closing database connection for volume 'Decomo'
Jun 02 23:55:18.898578 cnid_dbd[57522] {comm.c:207} (maxdebug:CNID): comm_rcv: got data on fd 5
Jun 02 23:55:18.898980 afpd[57517] {afp_dsi.c:108} (note:AFPDaemon): AFP statistics: 3177.09 KB read, 2524196.96 KB written
Jun 02 23:55:18.899005 afpd[57517] {dircache.c:615} (info:AFPDaemon): dircache statistics: entries: 2088, lookups: 10018, hits: 7503, misses: 2463, added: 2140, removed: 52, expunged: 52, evicted: 0
Jun 02 23:55:18.899020 afpd[57517] {dsi_stream.c:530} (maxdebug:DSI): dsi_stream_send(0 bytes): START
Jun 02 23:55:18.899033 afpd[57517] {dsi_stream.c:538} (maxdebug:DSI): dsi_stream_send(16 bytes): DSI header, no data
Jun 02 23:55:18.899045 afpd[57517] {dsi_stream.c:281} (maxdebug:DSI): dsi_stream_write(send: 16 bytes): START
Jun 02 23:55:18.899068 afpd[57517] {dsi_stream.c:325} (maxdebug:DSI): dsi_stream_write(send: 16 bytes): END
Jun 02 23:55:18.899089 afpd[57517] {afp_dsi.c:137} (info:AFPDaemon): Connection terminated
Jun 02 23:55:18.899899 afpd[57498] {main.c:149} (info:AFPDaemon): child[57517]: exited 1

Mac側はOS X v10.9.5で、サーバ側はFreeBSD 10.1-RELEASE。10.1RにはZFSのARCがメモリを食いつぶすバグがあるらしく、それが原因かと思って10-STABLEに更新するも、症状は相変わらず。

で、試行錯誤を続けていたが、Netatalk 3のsendfileを有効にしたらピタッとおさまった。正確には未だ出るけど、Netatalkとの接続は維持自体はされるようになった（自動で再接続されている模様）。おぼろげな記憶をたどると「ZFS環境でApache等のsendfileを有効にするとキャッシュの二重持ちになる可能性がある」という資料を見て、sendfile無効でNetatalk 3を作り直してたような気がしないでもなく、丁度その辺から問題が出たような気がする……。

時を同じくして、同サーバのSamba 4でファイル一覧の取得がタイムアウトしたり、動画が全く再生できなくなったりしていたのだが、こちらは逆にuse sendfile = yesを無効化したら直った。

全く以て謎だ…

Netatalkのログを見ようと思い立ちcat /var/log/netatalk.logしてみたら、ダダダーっとログが表示され一向に終わる気配がなかった。じーっと眺めてみると、3ヶ月前の日付が見える。ついでに、ログの粒度が物凄く細かい。

そういえばHATさんにログを提供するためにlog level = default:maxdebugにしてたなーと思いつつ、ログファイルのサイズを確認したら20GBまで膨らんでたｗｗｗ Netatalkのボリュームに同時アクセスすると、パフォーマンスが一気に落ちたり不安定だったのはこいつのせい？

maxdebugを止めるのは当然として、ログローテーションも行う事にした。

/etc/newsyslog.confに以下の一文を付け加え、# newsyslogすればよさそう。syslogのデフォルト設定に倣い、100KBでローテーションさせ、履歴は5つbz2圧縮で保持するようにした。

/var/log/netatalk.log			644  5	   100	*     JC

Portsのnetatalk3が3.0.3に更新された。

普通に更新してもいいのだが、折角なので[netatalk-ja:0155] Re: 3.0.2でPhotoshop CS5で濁音のファイルがセーブできないのパッチを適用してみる。

この問題を簡単に解説すると、netatalkがリソースフォークを処理する際にファイル名の文字コード変換(Unicode正規化含む)が正常に働かないため、リソースフォークを持ちファイル名に非ASCII文字を含むファイルが保存できないというもの。最近はリソースフォークを持つファイルも減ったようなので（かくいう私はPantherの後半の頃からMacを使い出したのでリソースフォーク全盛の頃を知らなかったりするのだが）、殆どのnetatalk環境では問題が起きないと思われる。ファイルシステムの文字コード絡みの問題なので、ZFSでUnicode正規化を強制してるような環境でも問題は起きない（まさにうちの環境ｗ）。

尚、パッチはTrunk開発ラインに取り込まれているので、3.0.4リリースの暁には直る模様。

果てしなく行儀が悪いけど、お手軽にportsにパッチする形でインストールする。

cd /usr/ports/net/netatalk3
sudo make patch
cd work/netatalk-3.0.3
sudo curl -O http://www003.upp.so-net.ne.jp/hat/files/git-bug511-forkname.patch.gz
sudo gzip -d git-bug511-forkname.patch.gz
sudo patch -p1 < git-bug511-forkname.patch
cd ../../
sudo make
sudo make install

パッチをあてると3.0.4devとしてインストールされるので確認。

$ afpd -v
afpd 3.0.4dev - Apple Filing Protocol (AFP) daemon of Netatalk
 
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
Foundation; either version 2 of the License, or (at your option) any later
version. Please see the file COPYING for further information and details.
 
afpd has been compiled with support for these features:
...

よし、OKだ。