INASOFT 管理人のひとこと

■常時起動Raspberry PiのminiDLNAがログ出力で日付時刻を付加してくれなくなったんだけど復活させたい

最近、仕事以外をサボってRaspberry Piイジリに精を出しておりました。

我が家ではRaspberry Pi 3 model B+を常時起動させており、miniDLNAでメディア配信をしていたり、ffmpegで変換を実施していたり、いくつかの処理を持たせています。今回、ffmpegの動作性能を僅かでも上げたい！という思いがあり、どうしようか考えていました。

Raspberry Pi 3 model B+に入れているのはRaspbianのjessieです。定期的にアップデートしているものの、根本は古い。というか、OSが32bitです。

最新のRaspberry Pi OSの64bitのものを入れれば、ffmpegの性能が僅かでも上がるのではないか？と思いまして、やってみることにしました。

(jessieの頃は、ffmpegは簡単に入れることができなかったし[当時の開発者間でケンカがあったらしい]、miniDLNAはソースコードをいじらないと日本語環境でまともに動かない状態でしたが、現在はどちらも簡単に入れる(apt install)ことができて、すごく便利)

ちなみに、このRaspberry PiにはUSB HDDが接続してありますが、OS起動と共にマウントしようとすると、稀に失敗します。起動できなくなります。Raspberry Piのところまで赴き、電源(micro USB)ケーブルを物理的に抜いてから挿さなければなりません。

そういった事情から、OS起動後少し待ってからUSB HDDをマウントしています。このマウントを待ってから、miniDLNA(ReadyMedia)を起動しています。これが、今回の伏線？になる部分です。

さて、古い時代のminiDLNAでは、ログに日付・時刻が付与されていました。

何が起きてしまったのか？

もちろん、起動時のオプションでログに日付時刻を付与するか否かをダイレクトに指定するようなものはありませんでしたし、minidlna.confに指定できるオプションの中にもありません。

ネット上でいろいろ検索しても、同じ問題で悩んでいる人はいませんでした。

どうしたらよいか……。

あ！ソースコードが公開されているのだから、直接原因を調べればいいのか！

これができる状況を作ってくれている制作者に、心より感謝したい！

というわけで、どのようにログが出力され、日付時刻の付与がどういう基準でON/OFFされているのかを、直接調べることにしました。

ひとまず、ログが出力されている箇所の手がかりの一つとして「scanner.c:855: info: Starting rescan」という個所がありましたので、scanner.cの855行目付近を調べてみることにします。

start_rescan(void)
{
  struct media_dir_s *media_path;
  char *esc_name = NULL;
  char *zErrMsg;
  const char *sql_files = "SELECT path, mime FROM details WHERE path NOT NULL AND mime IS NOT NULL;";
  const char *sql_dir = "SELECT path, mime FROM details WHERE path NOT NULL AND mime IS NULL;";
  int changes = sqlite3_total_changes(db);
  const char *summary;
  int ret;

  DPRINTF(E_INFO, L_SCANNER, "Starting rescan\n");

  /* Find and remove any dead directory links */

どうやらDPRINTFというものを使っているらしい。いわゆるdprintf()かな？と思ったのですが、実際の定義を調べてみると、log.h にて次のような定義となっていました。

#define DPRINTF(level, facility, fmt, arg...) do { log_err(level, facility, __FILE__, __LINE__, fmt, ##arg); } while (0)

void
log_err(int level, enum _log_facility facility, char *fname, int lineno, char *fmt, ...)
{
  va_list ap;

  if (level && level>log_level[facility] && level>E_FATAL)
    return;

  if (!log_fp)
    log_fp = stdout;

  // timestamp
  if (!GETFLAG(SYSTEMD_MASK))
  {
    time_t t;
    struct tm *tm;
    t = time(NULL);
    tm = localtime(&t);
    fprintf(log_fp, "[%04d/%02d/%02d %02d:%02d:%02d] ",
      tm->tm_year+1900, tm->tm_mon+1, tm->tm_mday,
      tm->tm_hour, tm->tm_min, tm->tm_sec);
  }

  if (level)
    fprintf(log_fp, "%s:%d: %s: ", fname, lineno, level_name[level]);
  else
    fprintf(log_fp, "%s:%d: ", fname, lineno);

どうやら、GETFLAGでSYSTEMD_MASKが立っていなければ、ログに時刻が出力される仕組みになっている様子。

SYSTEMD_MASKとは何か？

SETFLAG(SYSTEMD_MASK);をしている箇所があるはず、と調べてみると、minidlna.cの中で、miniDLNA起動時のコマンドラインオプションに -S が付けられていると、設定されることが分かりました。

#ifdef __linux__
  case 'S':
    SETFLAG(SYSTEMD_MASK);
    break;
#endif

オプション -S とは何か？ manでminidlnaのオプションを調べてみると、次のような記載がありました。

  -S  Stay foreground. Can be used when minidlnad is being managed by systemd

英語は読めない…。とりあえず機械翻訳に突っ込んでみると「フォアグラウンドにとどまります。 minidlnadがsystemdによって管理されているときに使用できます」だそうです。なるほど、わからん……。

わからんけど、いくらいじってぶっ壊しても良いのがRaspberry Piの醍醐味なので、-S を消す方法を探してみることにしました。

-S をどこで与えているのか？

/etc/init.d/minidlna かなと思ったが、最初に述べた通り（間接的な原因として）サービスの起動をHDDのマウント後にしたいとか、他にも、RAMディスクの準備後にしたいとかを実現するために、OS起動と同時に行わないようにしていたのでした。

結論から言えば、/lib/systemd/system/minidlna.service に定義されていました。

[Service]
User=minidlna
Group=minidlna

Environment=CONFIGFILE=/etc/minidlna.conf
Environment=DAEMON_OPTS=-r
EnvironmentFile=-/etc/default/minidlna

RuntimeDirectory=minidlna
LogsDirectory=minidlna
PIDFile=/run/minidlna/minidlna.pid
ExecStart=/usr/sbin/minidlnad -f $CONFIGFILE -P /run/minidlna/minidlna.pid -S $DAEMON_OPTS

この中で書かれている -S を単純に除去。壊してもいい覚悟です。(このページに書かれていることを参考にマネをしたい方も、Raspberry Pi環境を壊してよい覚悟の場合だけマネしてください)

この -S を除去し、サービスを再起動。

$ sudo systemctl stop minidlna
$ sudo systemctl start minidlna

すると、ログに日時が表示されるようになりました。

さて、-Sを取り除いたことによる悪影響を調べなければなりません。今回は単純にコマンドを打ち込んでminiDLNAを起動したわけですが、Raspberry Pi起動からの流れ（自動起動のスクリプトでUSB HDDのマウントを行い、スクリプトで正しくマウントできたことを確認してからスクリプトでminiDLNA起動）で起動できるのか？

実際やってみると、失敗しました。下記のコマンドで原因を表示させてみると、

$ sudo systemctl status minidlna

● minidlna.service - MiniDLNA lightweight DLNA/UPnP-AV server
     Loaded: loaded (/lib/systemd/system/minidlna.service; disabled; vendor preset: enabled)
     Active: inactive (dead)
       Docs: man:minidlnad(1)
             man:minidlna.conf(5)

 5月 31 20:01:51 raspberrypi2a systemd[1]: /lib/systemd/system/minidlna.service:4:
                                           Failed to add dependency on autofs, ignoring: Invalid argument
 5月 31 20:01:51 raspberrypi2a systemd[1]: Started MiniDLNA lightweight DLNA/UPnP-AV server.
 5月 31 20:01:52 raspberrypi2a systemd[1]: minidlna.service: Succeeded.
 5月 31 20:01:54 raspberrypi2a systemd[1]: /lib/systemd/system/minidlna.service:4:
                                           Failed to add dependency on autofs, ignoring: Invalid argument

「autofsへの依存関係を追加できない」とのこと。やはり、他の依存関係のサービスの起動を待たないとダメなんだろうな……。ということで、余裕のある時間(15秒以上)待ってからサービスを起動するようにしたら、無事に起動するようになりました。

念のため、3回くらいリトライをする仕込みを入れました。以下、起動時に実行しているシェルスクリプトです。

sleep 15
/usr/bin/systemctl start minidlna
sleep 3
/usr/bin/systemctl status minidlna
if [ $? -ne 0 ]; then
  echo minidlna起動リトライ。15秒待機。
  sleep 15
  /usr/bin/systemctl start minidlna
  sleep 3
  /usr/bin/systemctl status minidlna
  if [ $? -ne 0 ]; then
    echo minidlna起動リトライ。20秒待機。
    sleep 20
    /usr/bin/systemctl start minidlna
    sleep 3
    /usr/bin/systemctl status minidlna
    if [ $? -ne 0 ]; then
      echo minidlna起動失敗。
    fi
  fi
fi

$ sudo systemctl status minidlna

● minidlna.service - MiniDLNA lightweight DLNA/UPnP-AV server
     Loaded: loaded (/lib/systemd/system/minidlna.service; disabled; vendor preset: enabled)
     Active: active (running) since Tue 2022-05-31 20:02:09 JST; 3s ago
       Docs: man:minidlnad(1)
             man:minidlna.conf(5)
   Main PID: 715 (minidlnad)
      Tasks: 3 (limit: 839)
        CPU: 409ms
     CGroup: /system.slice/minidlna.service
             tq715 /usr/sbin/minidlnad -f /etc/minidlna.conf -P /run/minidlna/minidlna.pid -r
             mq716 /usr/sbin/minidlnad -f /etc/minidlna.conf -P /run/minidlna/minidlna.pid -r

 5月 31 20:02:09 raspberrypi2a systemd[1]: Started MiniDLNA lightweight DLNA/UPnP-AV server.

とりあえずこれでうまく行ったため、しばらく様子を見て観ることにします。上記以外の-S を取り外したことによる悪影響は、追って調べることにします。

ちなみに僕は普段は主にWindowsを使っていて、Linuxについては素人（仕事で使う程度）であることに加え、いくらでもぶっ壊してよい自宅のRaspberry Piであるから、特攻気分で手を加えています。大切な環境をいじる場合は慎重に。

最後に、全く関係ないけど sl コマンドをインストール。問題解決祝いに、花火を打ち上げるかの如く、盛大にSLを走らせたい。

$ sudo apt-get install sl

パッケージリストを読み込んでいます... 完了
依存関係ツリーを作成しています...完了
状態情報を読み取っています... 完了
以下のパッケージが新たにインストールされます:
  sl
アップグレード: 0 個、新規インストール: 1 個、削除: 0 個、保留: 0 個。
13.0 kB のアーカイブを取得する必要があります。
この操作後に追加で 56.3 kB のディスク容量が消費されます。
取得:1 http://deb.debian.org/debian bullseye/main arm64 sl arm64 5.02-1 [13.0 kB]
13.0 kB を 0秒 で取得しました (26.9 kB/s)
以前に未選択のパッケージ sl を選択しています。
(データベースを読み込んでいます ... 現在 43983 個のファイルとディレクトリがインストールされています。)
.../archives/sl_5.02-1_arm64.deb を展開する準備をしています ...
sl (5.02-1) を展開しています...
sl (5.02-1) を設定しています ...
man-db (2.9.4-2) のトリガを処理しています ...

$ man sl

$ sl

Broadcom BCM2837B0, Cortex-A53 （ARMv8）のARM 64bitのパワーが、単にSLを走らせるだけに費やされているかと思うと、なんだか楽しい。