Cheerfull days

Pythonを使っているときに、ログを取るのを怠ってエラーが見つからずに苦労したので、ちゃんとログを取りましょう、という話です。(Pythonに慣れている方には、おそらく常識レベルの話だと思います)

普通に処理をしている場合は、予期しない例外が発生すると標準エラー出力に例外のスタックトレースが出力されます。しかし、標準エラー出力を潰した後はスタックトレースが出力されません。

以下のような場合に問題になります。

• daemon化する場合
• スレッドを実行する場合

順に説明します。

daemon化する場合

double forkによるdaemon化については、Pythonでは以下のページの例のように行います。

Double forkによるプロセスのデーモン化と、ファイル変更時の自動サーバーリロードの実装 (Python)

この場合、標準エラー出力が潰されているので、 daemon化した後に例外が発生しても、 例外のスタックトレースはどこにも出力されません。

以下のようにすると、例外のログがloggerで出力できます。

def main():
    logger = getLogger()
    handler = FileHandler("./test.log")
    logger.addHandler(handler)

    daemonize() # double forkした後に標準エラー出力を潰す

    try:
        do_process() #ここで例外が発生したら、下のexceptでキャッチする
    except Exception as e:
        logger.exception("Exception {0} occured".format(e))

    

スレッドを実行する場合

さらに、daemon化してからスレッドを実行する場合、親スレッドのtry-exceptではスレッド内での例外は捕捉されず、例外のスタックトレースはどこにも出力されません。 スレッドのrun()で、例外を捕捉してログを出力する必要があります。

class TestThread(threading.Thread):
    _logger = getLogger(__name__)

    def run(self):
        try:
            self._do_process() #ここで例外が発生したら、下のexceptでキャッチする
        except Exception as e:
            self._logger.exception("Exception {0} occured".format(e))

def main():
    logger = getLogger()
    handler = FileHandler("./test.log")
    logger.addHandler(handler)

    daemonize() # double forkした後に標準エラー出力を潰す

    try:
        thread = TestThread()
        thread.start() # thread.run()で例外が発生しても、このtry-exceptでは捕捉できない
    except Exception as e:
        logger.exception("Exception {0} occured".format(e))

そんなこんなでうじゃうじゃ。

FreeBSDのzpoolの機能であるzvolを使ってボリュームを作り、そのボリュームをiSCSIを使ってWindowsマシンに公開しています。ボリュームの中のデータをFreeBSDから取得したい時の方法を調べたのでメモします。

要点は2つ。

• zvolのディスクイメージをマウントしたい場合は、ボリュームをsnapshot→cloneした上でvolmode=geomを使う
• NTFSのマウントには、ntfs-3g (fusefs-ntfsパッケージ) を使う

zvolのディスクイメージをマウントする方法

zvolをマウントするには、GEOMベースのツールが使えるように、ボリュームのプロパティを volmode=geom にする必要があります。

ただプロパティを変えただけではダメで、変えた後に再起動するか、snapshotを作った上でcloneし、cloneする際にプロパティを指定する必要があります。今回は後者で。

# zfs snapshot raidtank/iscsi/windows_disk@snap
# zfs clone -o volmode=geom raidtank/iscsi/windows_disk@snap raidtank/iscsi/windows_disk_clone

ここまでやると、 /dev/zvol/raidtank/iscsi/windows_disk_clonep* ができます(ボリューム内のディスクラベルに応じて)。

NTFSのボリュームをマウントする方法

NTFSのボリュームをマウントするには、fusefs-ntfsにあるntfs-3gを使います。

fusefs-ntfsをインストールしたら、

# ntfs-3g -o ro /dev/zvol/raidtank/iscsi/windows_disk_clonep2 /mnt

なお、fusefs-ntfsのインストール後に、/usr/sbin/mount_ntfs-3gというシンボリックリンクを手動で作った場合でも、「mount -t ntfs-3g (以下略)」ではなぜか失敗します(zvolだから?)。

参考文献

• vm-bhyveで使っているzvolをマウントする

今月誕生日なんですが、会員登録しているサイトから「誕生日の貴方にx%引きクーポン!」みたいなのが来るので、せっかくだからまとめてみます。

• yoyaq.com: 7000円(税込)以上で1000円引き
• ショップジャパン: 20%引き
• EPARKリラク&エステ: 3000円引き
• 東京シャツ(Yシャツ屋さん): 実店舗で500円引き
• ケンコーコム: 5000円(税込)以上で8%引き
• じぶん銀行: 1ヶ月ものスイッチ円定期預金、年利3%で31日間運用した金額を追加
• セブンネットショッピング: 1000円以上で100nanacoポイント
• JINS: オンラインショップで30%引き
• ユニクロ: 5000円(税抜)以上で500円引き
• とらのあな: 500円(税込)以上で8%引き
• アニメイト: オンラインショップで1点10%引き
• ココス: 誕生日の飲食代10%引き
• IKEA: 2000円(税込)以上で500円引き
• ドミノピザ: 3500円(税込?)以上で1000円引き(28日以内なら何度でも)
• キネゾー: 映画1回1400円
• GAP: 実店舗で定価品50%引き、オンラインショップで1000円引き(それぞれ1回)

4/1の3:08にmirakurunがエラーで再起動していたのでその時のログをメモ。

まず、mirakurun.stdout.log

<--- Last few GCs --->

[22698:0x27abf40] 120047592 ms: Scavenge 57.6 (269.9) -> 53.7 (269.9) MB, 2.7 / 0.0 ms allocation failure
[22698:0x27abf40] 120048005 ms: Scavenge 57.6 (269.9) -> 53.7 (269.9) MB, 2.1 / 0.0 ms allocation failure
[22698:0x27abf40] 120048221 ms: Scavenge 57.6 (269.9) -> 55.6 (269.9) MB, 3.2 / 0.0 ms allocation failure
[22698:0x27abf40] 120048241 ms: Scavenge 57.6 (269.9) -> 57.6 (277.9) MB, 5.1 / 0.0 ms allocation failure

<--- JS stacktrace --->
Cannot get stack trace in GC


次に、mirakurun.stderr.log

FATAL ERROR: Scavenger: semi-space copy
Allocation failed - process out of memory
1: node::Abort() [Mirakurun: Server]
2: 0x11e73ec [Mirakurun: Server]
3: v8::Utils::ReportOOMFailure(char const*, bool) [Mirakurun: Server]
4: v8::internal::V8::FatalProcessOutOfMemory(char const*, bool) [Mirakurun: Server]
5: 0xad230b [Mirakurun: Server]
6: v8::internal::Scavenger::ScavengeObject(v8::internal::HeapObject**, v8::internal::HeapObject*) [Mirakurun: Server]
7: v8::internal::Scavenger::Process(v8::internal::Scavenger::Barrier*) [Mirakurun: Server]
8: v8::internal::ScavengingTask::RunInParallel() [Mirakurun: Server]
9: v8::internal::ItemParallelJob::Task::RunInternal() [Mirakurun: Server]
10: v8::internal::ItemParallelJob::Run() [Mirakurun: Server]
11: v8::internal::Heap::Scavenge() [Mirakurun: Server]
12: v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [Mirakurun: Server]
13: v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [Mirakurun: Server]
14: v8::internal::Factory::NewRawTwoByteString(int, v8::internal::PretenureFlag) [Mirakurun: Server]
15: v8::internal::IncrementalStringBuilder::Extend() [Mirakurun: Server]
16: v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_(v8::internal::Handle, bool, v8::internal::Handle) [Mirakurun: Server]
17: v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_(v8::internal::Handle, bool, v8::internal::Handle) [Mirakurun: Server]
18: v8::internal::JsonStringifier::SerializeArrayLikeSlow(v8::internal::Handle, unsigned int, unsigned int) [Mirakurun: Server]
19: v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_(v8::internal::Handle, bool, v8::internal::Handle) [Mirakurun: Server]
20: v8::internal::JsonStringifier::Stringify(v8::internal::Handle, v8::internal::Handle, v8::internal::Handle) [Mirakurun: Server]
21: v8::internal::Builtin_JsonStringify(int, v8::internal::Object**, v8::internal::Isolate*) [Mirakurun: Server]
22: 0x2c33ba40697d


その時のメモリ使用量グラフ

クレジットカードの明細はマメにチェックするようにしていたのですが、2018/2/2の朝にWeb明細をチェックしたところ、1/29付けで、身に覚えのない「GOOGLE *ANIPLEX G.CO/HELPPAY」という利用先の9800円分の明細が2件見つかりました。

私はアニプレックスのアプリには課金していないので、「カードが不正利用された!?」と思い、すぐに行動を開始。

カードに不正請求の兆候! オラワクワクしてきたぞ!!

— 太鼓屋P (@taikoyaP) February 1, 2018

行動その1: 自分のGoogleアカウントの購入履歴をチェック(2/2 8:10)

ここで購入履歴があった場合、カード情報どころかアカウント自体が不正アクセスされているので非常にヤバいことになるのですが、ここでは購入履歴は発見できず。カードの情報だけ不正利用されているという事が分かりました。

Google経由で不正請求があったらしいので、カード会社経由とgoogle経由の両方から問い合わせだな。カード自体も作り替えるか否か。

— 太鼓屋P (@taikoyaP) February 1, 2018

行動その2: Googleのフォームに情報を送信(8:20)

Googleの「不正請求の報告」の手順に従ってフォームから事象を報告しました。すぐに自分のGmailアカウントに送信確認だけは来たのですが、結局その後電話しました(後述)。

行動その3: カードのサポートデスクに電話(8:30, 9:30)

不正利用も緊急だろ、と思い、カードの紛失盗難デスクに電話をしたのですが、「不正利用については営業時間内にサポートデスクに」と言われたので、9:30まで待ってからサポートデスクに電話。
そこで分かった事は、「サポートデスクではユーザーが見られるWeb明細より1日早く明細が見られるが、そこでは前述の2件以外にも、もう2件9800円の明細がある」ということ。
また、「カード自体が盗難されたわけではないので、カード会社としてはGoogleから取消決済をしてもらう必要がある」という事を言われました。
「カードを利用停止して再発行するか?」とは聞かれたのですが、Googleへ電話することにして一旦電話を切りました。

行動その4: Googleに電話(9:40)

Googleのフォームの送信確認メールの中に「お急ぎの場合は電話して下さい(9:00-)」とあったので、メールの返事を待たずに電話し、カード会社から言われたことと一緒に相談しました。
その結果、「調査して後ほどメールで回答する」という返事と、「カード情報が全て犯人の手に渡っていると思われるので、カードは再発行した方が良い」という意見を頂きました。
(後で思ったのですが、電話した時に、送信確認メールにあるケースIDを伝えた方が良かったですね。Googleの中で別ケースとしてカウントされて、別々に調査されていたようでした)

行動その5: カードのサポートデスクに電話(10:00)

Googleからの回答を伝え、こちらからは「カードを利用停止して再発行して下さい」とお願いしました。

行動その6: Googleからのメールを受信(18:30)

「4件の決済は、全て本人以外のGoogleアカウントであることが判明した。購入を行ったユーザーの情報は回答できない。過去120日前まで遡って不正な利用を全てカード会社に払い戻しを行った」という内容でした。
しかし、「結局何件の決済を払い戻ししたか」という情報は無かったので、若干不安でした。(確認しましたが「全部払い戻したので後で確認して欲しい」という返事でした)

googleから連絡があり、不正使用とみなして返金(決済取り消し)処理をしたとのこと。念のためクレジットカードも再発行処理済み。

— 太鼓屋P (@taikoyaP) February 2, 2018

行動その7: その後の不正利用の決済を確認する(2/3～2/5)

2/2に1/29付けの決済が見えたということで、私のカード会社では決済が見えるようになるまでに4日間のタイムラグがあるんですね。
ということで、2/5までに2/1までの決済が見えるようになり、全部で8件(78400円)の不正な利用がありました。
そのうちの一部です。

この時点ではまだ払い戻しが見えていなかったので、若干不安でした。

続報。不正請求は1回9800JPYが1日2回づつ行われていて、止めるまでに6回以上行われていたらしい(2/1以降に行われたかどうかは確認できていない)。枠がモリモリ減って行ってたんだなw

— 太鼓屋P (@taikoyaP) February 3, 2018

行動その8: 取消決済を確認 (2/5午後)

2/5午後にWeb明細をチェックしたところ、不正利用の決済が全て消えていたので、取り消されたことを確認できました。

振り返り

ほぼ完璧な対応ができたと思っています。
この文章を書いている2/5現在でまだ再発行のカードが届いていないので、定期支払いが必要な公共料金等を全部変える作業が残っているのを考えるとめんどくさくなりますが。

(2/6追記) カードを止める前に、モバイルSuicaとnanacoに上限までチャージしておけば良かった、とは思っています。

余談

2/2にカードを停止して、その日の午後にAmazonから発送された予約商品(ヲタ恋5巻)があったのですが、どうやらちゃんとカードから決済されたようです。停止前にオーソリで枠を確保してある物に関しては決済できるのか、と思っています(Amazonは出荷準備の時点でオーソリを行い、出荷時点で決済する)。

そんなこんなでうじゃうじゃ。