はじめに

さくらVPS 512MB / Debian 12 上で動かしているハニーポット (OpenCanary) の観測ログを、ブラウザでURLを開くだけで最新の攻撃データが見られるダッシュボード にするまでの構築記録です。

単純なパイプライン構築の話に見えて、実際には運用中の隠れた不具合（fd枯渇）やrcloneの仕様の罠に次々ハマりました。同じ構成を組む方向けに、トラブルと対処をまとめます。

TL;DR

ゴール: OpenCanaryログ → Google Drive → スプレッドシート → Looker Studio の自動パイプライン
構成: rclone(6hごとcron) + Google Apps Script(6hごとトリガー) + Looker Studio
ハマったトラブル: ①EMFILE(fd枯渇) ②rclone md5エラー ③root cronの認証ズレ ④時系列描画失敗 ⑤JSON内フィールドの列分離
結論: 書き込み中ファイルはスナップショット経由、cronは実行≠成功、可視化は粒度集約が肝

対象読者

OpenCanary等のハニーポットを運用していて、ログを可視化したい方
rcloneでDriveバックアップを組んでいる方
Looker Studioで時系列・集計ダッシュボードを作りたい方

完成アーキテクチャ

[VPS]
OpenCanary (Twisted, LimitNOFILE=65536)
  ↓ JSON append
/home/canary/opencanary.log (logrotate: 5MB×7世代+gzip)
  ↓ snapshot cp (canary権限)
/tmp/opencanary.log.snapshot
  ↓ rclone copyto --config (6hごとcron)
[Google Cloud]
Google Drive: opencanary-logs/ik1-xxx-xxxxx/YYYY-MM/
  ↓ Apps Script (時間トリガー6h)
スプレッドシート logs シート
  ↓ データソース接続
Looker Studio
  ↓
ブラウザURL ← 開くだけで最新

トラブル1: EMFILE（fdディスクリプタ枯渇）

症状

ある日、ログが書かれなくなった。プロセスは生きているのに、ログだけ止まっている。

# プロセスは active
$ sudo systemctl status opencanary
   Active: active (running)

# でもログの最終更新は数日前で止まっている
$ sudo stat /home/canary/opencanary.log
Modify: 2026-06-06 23:05:33 +0900

切り分け

iptablesカウンタで「攻撃が届いているか」を確認。

$ sudo iptables -t nat -L PREROUTING -n -v
39061  packets  tcp dpt:22 redir ports 2222
52380  packets  tcp dpt:23 redir ports 2300

トラフィックは大量に届いている。つまり「アクセスが無いだけ」ではなく、プロセスが受けられていない。

journaldを掘ると犯人が出た。

$ sudo journalctl -u opencanary --since "2026-06-06 22:00" | grep -i error
... EMFILE encountered ... (大量)

原因と対処

EMFILE = Too many open files。Soft limitが1024で、攻撃の連射によりソケットを使い切っていた。

$ sudo cat /proc/<PID>/limits | grep "open files"
Max open files    1024    524288    files
                  ^Soft   ^Hard

systemdでfd上限を引き上げる。

$ sudo systemctl edit opencanary

[Service]
LimitNOFILE=65536

$ sudo systemctl daemon-reload   # これを忘れると反映されない
$ sudo systemctl restart opencanary

確認：

$ NEWPID=$(systemctl show -p MainPID --value opencanary)
$ sudo cat /proc/$NEWPID/limits | grep "open files"
Max open files    65536    524288    files

教訓: active (running) ≠ 正常。Twisted系アプリはfdを大量に使うので LimitNOFILE を最初から設定する。systemctl edit は daemon-reload 必須。

トラブル2: rcloneの認証ズレ（root cron vs 一般ユーザー）

症状

Driveのバックアップが数日前で止まっていた。

$ sudo -u canary rclone lsl gdrive:opencanary-logs/ik1-xxx-xxxxx/2026-06/
  9268752 2026-06-03 00:00:23  opencanary.log.1
  ...                          （これ以降が古い）

切り分け

cronは動いている。

$ sudo journalctl _COMM=cron --since "2026-06-02" | grep -i backup | tail
Jun 08 06:00:01 ... CRON[...]: (root) CMD (/usr/local/bin/opencanary-backup.sh)

スクリプトを見ると犯人がいた。

$ sudo cat /usr/local/bin/opencanary-backup.sh
export RCLONE_CONFIG="/home/admin01/.config/rclone/rclone.conf"  # ← root cronなのにadmin01の設定

rcloneのトークンは canary の設定にしかない。root cronが別ユーザーの（不完全な）設定を読んで認証失敗していた。

対処

# Before
export RCLONE_CONFIG="/home/admin01/.config/rclone/rclone.conf"
$RCLONE_CMD copy ...

# After
RCLONE_CONFIG_PATH="/home/canary/.config/rclone/rclone.conf"
sudo -u canary $RCLONE_CMD --config "$RCLONE_CONFIG_PATH" copy ...

--config 明示（環境変数は sudo -u で継承されないことがある）+ sudo -u canary で実行ユーザー統一。

教訓: cronの実行記録は成功記録ではない。set -euo pipefail でスクリプト内エラーを可視化する。

トラブル3: md5 hash differ（書き込み中ファイルの転送）

症状

$ sudo tail /var/log/opencanary-backup.log
ERROR : corrupted on transfer: md5 hash differ 
  "02682dd8..." vs "aa5d2c3a..."
Transferred: 14.773 MiB / 14.773 MiB, 100%

転送は100%完了しているのにmd5が食い違う。

原因

転送対象 opencanary.log は書き込み中。50秒の転送中にhoneypotが追記し、送信前と送信後でハッシュが変わっていた。

対処：スナップショット方式

転送前に /tmp へ静的コピーを作り、それを送る。

#!/bin/bash
set -euo pipefail

LOG_DIR="/home/canary"
RCLONE_REMOTE="gdrive:opencanary-logs"
YEAR_MONTH=$(date +%Y-%m)
HOSTNAME=$(hostname)
RCLONE_CMD="/usr/bin/rclone"
RCLONE_CONFIG_PATH="/home/canary/.config/rclone/rclone.conf"
LOG_FILE="/var/log/opencanary-backup.log"
DEST="$RCLONE_REMOTE/$HOSTNAME/$YEAR_MONTH"

# 現行ログを静的スナップショットにコピー
SNAPSHOT="/tmp/opencanary.log.snapshot"
sudo -u canary cp "$LOG_DIR/opencanary.log" "$SNAPSHOT"

# copyto で出力ファイル名を制御してアップロード
sudo -u canary $RCLONE_CMD --config "$RCLONE_CONFIG_PATH" \
    copyto "$SNAPSHOT" "$DEST/opencanary.log" \
    --no-traverse --log-file="$LOG_FILE" --log-level INFO 2>&1

sudo -u canary rm -f "$SNAPSHOT"

# ローテーション済みは変化しないのでそのまま
sudo -u canary $RCLONE_CMD --config "$RCLONE_CONFIG_PATH" \
    copy "$LOG_DIR/" "$DEST/" \
    --include "opencanary.log.*" \
    --no-traverse --log-file="$LOG_FILE" --log-level INFO 2>&1

sudo -u canary tee -a "$LOG_FILE" > /dev/null <<< "[$(date)] Backup completed"

ポイント：

cp で静的スナップショット化（最重要）
copy ではなく copyto（出力ファイル名制御）
全コマンド sudo -u canary で統一（ログ書き込みも tee で）

教訓: 書き込み中ファイルをそのままrcloneしない。スナップショット経由が王道。

補足：スクリプト編集時、cat > file << 'EOF' 形式のヒアドキュメントをターミナルに丸ごと貼ると、コマンド自体が中身になる事故が起きる。nanoで書いて head -3・tail -5 で確認するのが安全。

トラブル4 & 5: Apps Script と Looker Studio

Apps Script: Drive → スプレッドシート橋渡し

Looker StudioはJSON直読み不可なので、中間にスプレッドシートを挟む。Apps Scriptが6時間ごとにDriveのログを読んで整形・書き込みする。

主要な設計：

// logtypeを人間可読ラベルに変換
const LOGTYPE_MAP = {
  3000: 'http_get',
  4002: 'ssh_login_attempt',
  6001: 'telnet_login_attempt',
  // ...
};

// logdataからユーザー名・パスワードを別列に抽出
function extractCredentials_(logdata) {
  let data = logdata;
  if (typeof logdata === 'string') {
    try { data = JSON.parse(logdata); } catch (e) { return {username:'', password:''}; }
  }
  // OpenCanaryは大文字キー、念のため小文字・別名も対応
  const username = data.USERNAME || data.username || data.user || '';
  const password = data.PASSWORD || data.password || data.pass || '';
  return { username, password };
}

ポイント：

集計したいフィールド（username/password）は独立列に展開（ネストJSONのままだとLookerで集計できない）
logtypeを人間可読ラベルに
重複排除（現行ログとローテーション済みが時間帯で重なる）
utc_timeでソート
壊れた行はtry-catchでスキップ、.gzは Utilities.ungzip

トリガー: ⏰アイコン → 関数 updateHoneypotLogs / 時間主導型 / 6時間おき。

実行時間制限（1回6分）に注意。ログ量が増えたら差分読み込みへ改良が必要。

Looker Studio: ダッシュボード構築

データソースに logs シートを接続し、グラフを配置。

グラフ	タイプ	ディメンション	指標
総攻撃数	スコアカード	-	Record Count
攻撃元IP TOP10	横棒	src_host	Record Count
サービス別内訳	円	logtype_label	Record Count
攻撃推移	時系列	utc_time(粒度:日)	Record Count
パスワードTOP20	横棒	password	Record Count
データ期間	スコアカード×2	utc_time(Min/Max)	-

ハマりポイント

① 時系列が「データが多すぎて作れない」

utc_timeがミリ秒精度でデータ点が数万個になる。→ ディメンションの粒度を「日」または「時間」に集約。

② パスワードランキングの1位が空欄

HTTP GETなどログイン試行でない行はpassword空欄。→ グラフにフィルタ「passwordが空でない」を追加。

③ Min/Max集計が出ない

utc_timeが文字列認識。→ データソースでフィールドタイプを「日付と時刻」に。なおISO形式なので文字列のままでも辞書順=時系列順でMin/Maxは実質正しく動く。

④ 追加した列がLookerで選べない

→ 「追加済みのデータソースの管理」→「編集」→「フィールドを再読み込み」。

完成

ブラウザでURLクリック
  → Looker Studio がスプレッドシート参照
  → スプレッドシートは Apps Script が6hごとにDriveから取り込み
  → Drive は rclone cronが6hごとにVPSから取り込み

更新ラグは最大6時間。URLをブックマークすればいつでも最新の攻撃トレンドが見られる。

まとめ：学んだこと

active (running) は信用しない。ログ更新時刻で死活監視
Twisted系は LimitNOFILE=65536 を最初から
書き込み中ファイルはスナップショット経由で転送
cron実行記録 ≠ 成功記録。set -euo pipefail で可視化
設定ファイルの所有ユーザーと実行ユーザーは統一（--config明示）
Looker StudioはJSON直読み不可。中間ストアが必要
集計フィールドは独立列に展開してから可視化
時系列は粒度を日/時間に集約、集計グラフは空欄フィルタ

参考リンク

補足

物語ベースの詳細な構築記（全3回）は自身のブログ「ハニーレポート」で公開しています。本記事の手順とスクリプト一式をまとめたPDFガイドもnoteで配布予定です。

最後まで読んでいただきありがとうございました。誤りがあれば編集リクエストやコメントでご指摘ください。