最近はずっと安定した録画環境構築を目指して頑張っており、これを続けてきたのですが、QSVによるエンコードエンコード環境を作り、join_logo_scpの導入や改造も含めてほぼ完ぺきな環境を作り上げたと思っていました。
しかし、安定環境なのかは後で発覚するもので、数日たつと動かなくなったりすることも出てくるわけです。今回もそのパターンだったのですが、録画・予約・録画済みデータの閲覧・エンコードの全てができなくなる状態になりました。
EPGStationの画面にアクセスできることから、pm2にのかっているEPGStationのServiceは生きていると判断、チューナの不具合の場合は、録画済みデータが見れなくなることはないのでmirakurunやチューナ側の問題でもなさそうという感じで検討はつけていましたが、個人的に出会ったことのないパターンだったので共有しておこうという感じの話になります。
結果的にEPGStaion側の問題でもなく、使っているUbuntu Serverのアップデートの設定の問題でした。とはいえ、誰もEPGStationでSQLITE_BUSYが出た話はなかったので珍しい話のようなので、確認方法とか解決方法の備忘録を残しておきます。
目次
環境
まず環境です。自作PCだとマシン側に問題がある場合もあるので残しておきます。
使っていたのは中華ミニPCですが、ほぼ100%AZWのOEMの製品なので酷く信頼性がないPCというわけではないです。AZWはBeellinkの名前で自社のPCを売っている中国の企業です。今まで2製品ほど買ったことがありますが、３年ほど酷使していますが、U59の方は録画サーバーとして安定していることを確認しています(参考: U59 、Mini S12)。今回はJingshaというブランドでAliExpressで売っていたのを使用しています。
- Core i3 1215U
- RAM DDR4-3200 SO-DIMM 4*2GB
- Ubuntu Server 24.04 LTS
- EPGStation ver. 2.10.0
- MIrakurun ver. 3.9.0-rc.4
ひとまずこんな感じです。インストール手順は基本的には以下のページに書いた通りにしています。一つ目はRaspbery Piのですが、気異本的に同じ手順でEPGStaionです。
気になる人だけ読めば大丈夫です。
症状
EPGStaionの録画管理の画面にアクセスしてみると、
- 予約情報習得に失敗
- 録画中データ取得に失敗
- 録画済みデータ取得に失敗
- 予約データ取得に失敗
の4つが出てきます。ただ、EPGStation自体は立ち上がっているので、EPGStationが動いていないというわけでも無いようです。
ちなみに、ストレージの情報を見るとデータが表示されているので、録画先を見失っているわけでもなさそうです。録画先を見失っているだけだと、録画済みのデータや予約データは見ることができます。
チューナ側の不具合だと数日前から録画ができていなくて、それまでに取得した予約情報が尽きていると、番組表に何も表示されないという不具合が出ますが、今回はある日突然という感じだったので、これも違います。
Mirakurun側が動いていない場合は、MirakurunのWebUIにアクセスすれば確認できます。デフォルトから変更を加えていなければブラウザでIP:40772とすれば確認できます。これも正常に動作していることを確認できました。Logの方を見ても正常なようです。
この感じからするにDBが怪しいだろうなという検討ぐらいはこの段階でついていました。
確認方法
MIrakurunのログ確認方法は上で書いた通りですが、他のログも確認してみましょう。EPGStationのログを確認します。以下の場所にあります。
EPGStation/logs/Operator/System.log追ってみると初めてErrorが出てきたのがこの部分でした。
[2025-02-07T06:34:31.256] [ERROR] system - QueryFailedError: SQLITE_BUSY: database is locked
at Statement.handler (/YOUR_EPGStaion_dir/node_modules/typeorm/driver/sqlite/SqliteQueryRunner.js:88:37) {
query: 'DELETE FROM "recorded_history" WHERE "endAt" <= 1731101661224',
parameters: [],
driverError: [Error: SQLITE_BUSY: database is locked] {
errno: 5,
code: 'SQLITE_BUSY'
},
errno: 5,
code: 'SQLITE_BUSY'
}SQLITE_BUSYになっていますね。私はMariaDBとかではなくSQLiteをつかっているのでこういうエラーになっています。というわけでSQLiteに問題が発生していることに気づきました。
さて、SQLiteのエラーというとどうしてもトランザクションを出している側に問題があると考えたくなるのですが、ポイントはエラーの出ていた時間です。
この時間の前後は数時間は録画していないですし、過剰にトランザクションを出しているわけでもないはずですしこれだけだと謎です。
チューナ関係がおかしくないかを見てみます。
dmesg -Tここで見てみると、チューナは全くおかしくないことがログだとわかります。しかし、気になるの記述を発見。
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping systemd-journald.service - Journal Service...
[Fri Feb 7 06:32:38 2025] systemd[1]: netplan-ovs-cleanup.service - OpenVSwitch configuration for cleanup was skipped because of an unmet condition check (ConditionFileIsExecutable=/usr/bin/ovs-vsctl).
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-networkd-wait-online.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped systemd-networkd-wait-online.service - Wait for Network to be Configured.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping systemd-networkd-wait-online.service - Wait for Network to be Configured...
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping systemd-networkd.service - Network Configuration...
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping systemd-resolved.service - Network Name Resolution...
[Fri Feb 7 06:32:38 2025] systemd[1]: Started avahi-daemon.service - Avahi mDNS/DNS-SD Stack.
[Fri Feb 7 06:32:38 2025] systemd-journald[373]: Received SIGTERM from PID 1 (systemd).
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping systemd-timesyncd.service - Network Time Synchronization...
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping thermald.service - Thermal Daemon Service...
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping upower.service - Daemon for power management...
[Fri Feb 7 06:32:38 2025] systemd[1]: smbd.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped smbd.service - Samba SMB Daemon.
[Fri Feb 7 06:32:38 2025] systemd[1]: smbd.service: Consumed 7.862s CPU time, 202.2M memory peak, 6.7M memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-networkd.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped systemd-networkd.service - Network Configuration.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-networkd.service: Consumed 32.152s CPU time, 4.0M memory peak, 900.0K memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopping systemd-udevd.service - Rule-based Manager for Device Events and Files...
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-journald.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped systemd-journald.service - Journal Service.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-journald.service: Consumed 5.163s CPU time, 24.7M memory peak, 1.1M memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-timesyncd.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped systemd-timesyncd.service - Network Time Synchronization.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-timesyncd.service: Consumed 9.340s CPU time, 2.5M memory peak, 860.0K memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting systemd-journald.service - Journal Service...
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting systemd-timesyncd.service - Network Time Synchronization...
[Fri Feb 7 06:32:38 2025] systemd[1]: ssh.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped ssh.service - OpenBSD Secure Shell server.
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting ssh.service - OpenBSD Secure Shell server...
[Fri Feb 7 06:32:38 2025] systemd[1]: Started multipathd.service - Device-Mapper Multipath Device Controller.
[Fri Feb 7 06:32:38 2025] systemd-journald[773857]: Collecting audit messages is disabled.
[Fri Feb 7 06:32:38 2025] systemd[1]: upower.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped upower.service - Daemon for power management.
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting upower.service - Daemon for power management...
[Fri Feb 7 06:32:38 2025] systemd[1]: nmbd.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped nmbd.service - Samba NMB Daemon.
[Fri Feb 7 06:32:38 2025] systemd[1]: nmbd.service: Consumed 48.474s CPU time, 10.9M memory peak, 2.4M memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: Started polkit.service - Authorization Manager.
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting nmbd.service - Samba NMB Daemon...
[Fri Feb 7 06:32:38 2025] systemd[1]: Started ssh.service - OpenBSD Secure Shell server.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-udevd.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped systemd-udevd.service - Rule-based Manager for Device Events and Files.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-udevd.service: Consumed 5.797s CPU time, 59.7M memory peak, 3.4M memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-resolved.service: Deactivated successfully.
[Fri Feb 7 06:32:38 2025] systemd[1]: Stopped systemd-resolved.service - Network Name Resolution.
[Fri Feb 7 06:32:38 2025] systemd[1]: systemd-resolved.service: Consumed 8.887s CPU time, 7.8M memory peak, 2.0M memory swap peak.
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting systemd-resolved.service - Network Name Resolution...
[Fri Feb 7 06:32:38 2025] systemd[1]: Starting systemd-udevd.service - Rule-based Manager for Device Events and Files...
[Fri Feb 7 06:32:38 2025] systemd[1]: Started systemd-timesyncd.service - Network Time Synchronization.
[Fri Feb 7 06:32:38 2025] systemd[1]: Started systemd-journald.service - Journal Serviceエラーが発生する2分前にSystemd関係のサービスが色々と止まっています。PCが再起動したわけでもないのにSystemd周りが再起動しています。
これが原因なのは間違いなさそうなので、この現象を考えてみることにします。
ただ、Systemdがフリーズでもなんでもなく再起動するはずもないのと、録画サーバーが突然録画できなくなったときに以前にシステムのアップデートでドライバを見失っていたことを思い出したのでその部分を調べてみると結果としてビンゴでした。
まずUbuntuの自動更新について下調べをしてみるといこちらのページがヒットしました。以下のコマンドでUbuntuの自動更新のコマンドの状況を調べてみます。
$ cat /etc/apt/apt.conf.d/20auto-upgrades
APT::Periodic::Update-Package-Lists "1";
APT::Periodic::Unattended-Upgrade "1";値が1のとき有効なので、有効であるということですね。これで十分怪しいのですが、さらなる確証を探していきます。このコマンドが走る時間を調べます。
$ sudo systemctl list-timers apt-daily*
NEXT LEFT LAST PASSED UNIT ACTIVATES
Sun 2025-02-09 05:44:30 JST 16h Sat 2025-02-08 10:55:01 JST 2h 43min ago apt-daily.timer apt-daily.service
Sun 2025-02-09 06:17:23 JST 16h Sat 2025-02-08 06:50:49 JST 6h ago apt-daily-upgrade.timer apt-daily-upgrade.serviceこれによると、次の日の同じような時間帯に実施されていたことがわかります。以前は06:34だったことを考えると、16分ずれていますが、その理由は以下のコマンドで調べることができました。
$ cat /lib/systemd/system/apt-daily-upgrade.timer
[Unit]
Description=Daily apt upgrade and clean activities
After=apt-daily.timer
[Timer]
OnCalendar=*-*-* 6:00
RandomizedDelaySec=60m
Persistent=true
[Install]
WantedBy=timers.targetこのapt-daily-upgrade.timerとやらはRandamizedDelaySecの記述にある通り、毎朝6:00から60分の間にランダムで実行されるようです。ということはトラブルが発生した日に06:34に実行されていたのも正しい動作であることも確証が取れあました。ほぼ100%この自動更新が原因だとみて間違いないでしょう。
Ubuntu Serverの自動更新を無効にする
これは先ほど出てきた/etc/apt/apt.conf.d/20auto-upgradesの設定ともう一つの項目を触るだけです。値を0にすればよいです。
$cat /etc/apt/apt.conf.d/20auto-upgrades
APT::Periodic::Update-Package-Lists "0";
APT::Periodic::Unattended-Upgrade "0";こうなっていればOK。
たったこれだけです。これで録画サーバーの無用なトラブルを防げます。ただ、外部に直でつながっているサーバはそうもいかないと思うのでそこは管理の仕方を気を付けないといけませんね。
まとめ
EPGStationでSQLITE_BUSY database is lockedが出て録画ができなかった話でした。
設定の問題やチューナ側の問題で録画できなかったというのは今までもあったのですが、このパターンは初めてだったので残しておきます。確認方法なども今回は私は初めてこういったやり方をしたので私自身が次に忘れていたりしそうです。
結果的にはUbuntu Serverの設定の問題でしたが、自動更新を無効にするだけなので、操作自体は簡単だったというオチでした。以前にも録画サーバーを組んだときにpx4_drvが自動アップデートで見失うという問題が発生してそのサーバーでも自動アップデートを無効にしており、間接的に対策ができていたので気づけなかったんですよね。今度からは真っ先に自動更新を無効にしようと思います。
以上です。お読みいただきありがとうございました。