hayabusa
hayabusa copied to clipboard
Yamato-Security
[bug] v1.4.2+ Hayabusa will randomly miss a few events
Describe the bug
Different detection results for each run to same rule and directory
Step to Reproduce Steps to reproduce the behavior:
- Download hayabusa-1.4.2-windows-64-bit.zip from release page and unzip.
- Open command prompt(Run as Administrator).
- Execute following command
hayabusa-1.4.2-win-x64.exe -d ../hayabusa-sample-evtx -o 1.csv - Execute following command
hayabusa-1.4.2-win-x64.exe -d ../hayabusa-sample-evtx -o 2.csv - difference detection count 3. result and 4. result.
Expected behavior
Same detection results count to same rule and directory.
Screenshots If applicable, add screenshots to help explain your problem.
Environment (please complete the following information):
- OS: Microsoft Windows 11
- hayabusa version: v1.4.2
Additional context Add any other context about the problem here.
ref : https://github.com/Yamato-Security/hayabusa/pull/631#issuecomment-1202913949
そもそもv1.4.2の段階で同じバイナリ、同じルール、同じディレクトリに複数回実行したときに検知回数が異なるという問題を確認しました。 Uniqueの検知回数は一致していますが、原因がよくわからない状態になっています。可能性があるとしたら時間内でのレコードの並びが実行時に一定になっていないことが原因かもしれません。 以下はv1.4.2の結果となります。v1.4.1は別途確認予定
1回目 (hayabusa.exe -d hayabusa-sample-evtx -o main1.csvとして実行) Results Summary:
Total events: 62168 Data reduction: 43137 events (69.39%)
Total detections: 31206 Total critical detections: 48 Total high detections: 6132 Total medium detections: 1283 Total low detections: 6666 Total informational detections: 17077
Unique detections: 519 Unique critical detections: 16 Unique high detections: 234 Unique medium detections: 141 Unique low detections: 75 Unique informational detections: 53
Date with most total critical detections: 2019-07-19 (14) Date with most total high detections: 2016-09-20 (3653) Date with most total medium detections: 2021-04-22 (146) Date with most total low detections: 2016-09-20 (3780) Date with most total informational detections: 2016-08-19 (2105)
2回目 (hayabusa.exe -d hayabusa-sample-evtx -o main2.csvとして実行) Results Summary:
Total events: 62168 Data reduction: 43139 events (69.39%)
Total detections: 31200 Total critical detections: 48 Total high detections: 6132 Total medium detections: 1282 Total low detections: 6662 Total informational detections: 17076
Unique detections: 519 Unique critical detections: 16 Unique high detections: 234 Unique medium detections: 141 Unique low detections: 75 Unique informational detections: 53
Date with most total critical detections: 2019-07-19 (14) Date with most total high detections: 2016-09-20 (3653) Date with most total medium detections: 2021-04-22 (146) Date with most total low detections: 2016-09-20 (3780) Date with most total informational detections: 2016-08-19 (2105)
v 1.4.1の結果は以下の通り。3回実行して検知数が変わらなかったためv1.4.2.での対応が原因ということが分かった
- 1回目
Results Summary:
Total events: 62168
Data reduction: 43137 events (69.39%)
Total detections: 31212
Total critical detections: 48
Total high detections: 6132
Total medium detections: 1284
Total low detections: 6667
Total informational detections: 17081
Unique detections: 519
Unique critical detections: 16
Unique high detections: 234
Unique medium detections: 141
Unique low detections: 75
Unique informational detections: 53
Date with most total critical detections: 2019-07-19 (14)
Date with most total high detections: 2016-09-20 (3653)
Date with most total medium detections: 2021-04-22 (146)
Date with most total low detections: 2016-09-20 (3780)
Date with most total informational detections: 2016-08-19 (2105)
- 2回目
Results Summary:
Total events: 62168
Data reduction: 43137 events (69.39%)
Total detections: 31212
Total critical detections: 48
Total high detections: 6132
Total medium detections: 1284
Total low detections: 6667
Total informational detections: 17081
Unique detections: 519
Unique critical detections: 16
Unique high detections: 234
Unique medium detections: 141
Unique low detections: 75
Unique informational detections: 53
Date with most total critical detections: 2019-07-19 (14)
Date with most total high detections: 2016-09-20 (3653)
Date with most total medium detections: 2021-04-22 (146)
Date with most total low detections: 2016-09-20 (3780)
Date with most total informational detections: 2016-08-19 (2105)
- 3回目
Total events: 62168
Data reduction: 43137 events (69.39%)
Total detections: 31212
Total critical detections: 48
Total high detections: 6132
Total medium detections: 1284
Total low detections: 6667
Total informational detections: 17081
Unique detections: 519
Unique critical detections: 16
Unique high detections: 234
Unique medium detections: 141
Unique low detections: 75
Unique informational detections: 53
Date with most total critical detections: 2019-07-19 (14)
Date with most total high detections: 2016-09-20 (3653)
Date with most total medium detections: 2021-04-22 (146)
Date with most total low detections: 2016-09-20 (3780)
Date with most total informational detections: 2016-08-19 (2105)
@YamatoSecurity 確認しました。v1.4.1の内容から検知数に関連する内容は #479 のみであることが分かりました。 おそらくDashMapにおける同一秒数に対して、データの投入の順序の誤差が発生してたためおそらくaggregation関連のルールの検知が発生したり、しなかったりしたことで検知件数にぶれが生じたのではないかと思われます。
改善:
- --update-rules オプションを利用する時に、更新対象のレポジトリを--rulesオプションで指定できるようにした。 (https://github.com/Yamato-Security/hayabusa/issues/615) (@hitenkoku)
- 並列処理の改善による高速化。 (https://github.com/Yamato-Security/hayabusa/issues/479) (@kazuminn)
- --outputオプションを利用したときのRulePathをRuleFileに変更した。RuleFileは出力するファイルの容量を低減させるためにファイル名のみを出力するようにした。 (https://github.com/Yamato-Security/hayabusa/issues/623) (@hitenkoku)
🐛 バグ修正:
- cargo runコマンドでhayabusaを実行するとconfigフォルダの読み込みエラーが発生する問題を修正した。 (https://github.com/Yamato-Security/hayabusa/issues/618) (@hitenkoku)
こちらでも確認できました。3回連続で実行したら、3回目で検知数が２件減りました。 以下のイベントが検知されませんでした:
2016-08-18 23:49:40.000 +09:00,IE10Win7,Sec,4624,info,,4764,Logon (Type 2 Interactive) *Credentials stored in memory*,User: IEUser | Comp: IE10WIN7 | IP-Addr: 127.0.0.1 | LID: 0x1b2fd,4624_LogonType-2-Interactive.yml,../hayabusa-sample-evtx/DeepBlueCLI/many-events-security.evtx
2016-08-19 00:29:29.859 +09:00,IE10Win7,Sec,4672,info,,4806,Admin Logon,User: IEUser | PrivList: SeSecurityPrivilege SeTakeOwnershipPrivilege SeLoadDriverPrivilege SeBackupPrivilege SeRestorePrivilege SeDebugPrivilege SeSystemEnvironmentPrivilege SeImpersonatePrivilege | LID: 0x1aae1,4672_AdminLogon.yml,../hayabusa-sample-evtx/DeepBlueCLI/many-events-security.evtx
1.4.1の結果と比較したら、大体毎回数件のイベントを見逃しています。検証の時に気づかなくて申し訳ありません。
ありがとうございます。私の方ではどのルールが検出されなかったのかまでは調べていなかったので助かります。 ご指摘いただいた内容のルールを見てみたところ特にcountなどのaggregationconditionが利用されているようではないみたいですね……。 提示してもらったルールでconditionで使われているのはandとnotくらいでした。その場合であれば1レコードで判定ができるものなので、なぜ漏れたかがよくわからないですね。 もう少し確認してみます
そうですね。10件も減っている場合もあるので、countは関係なさそうです。何かのrace conditionで特定しにくいかもしれません。
本件、わたくしの追加した処理が原因のようで、申し訳ございません。
原因がわかりました。何らかの原因で、タイムラインsortする処理がv1.4.1本体に取り込まれていなかったのが原因のようです。 ↓ソートする処理。 https://github.com/Yamato-Security/hayabusa/pull/622/files#diff-e6c361eb7b576e57173f4e9bce9f7b5c7d68031a3335154fe046417a4cae0fc9R246
なぜ、本体にちゃんと取り込まれていないかは、わたくしの方で把握できていない状態です。
@YamatoSecurity あー。1.4.2なんですね。見るバージョンを間違えていて、入っていました。
この話は忘れてください。
https://github.com/Yamato-Security/hayabusa/issues/639#issuecomment-1205064571
ご指摘いただいた個所はタイムラインをソートする処理自体は組み込まれていると思われます。(指摘されたところはv1.4.2で入っている。v1.4.1ではそもそも入っていない) そもそも該当の処理自体は既に検知結果が入っている状態であり、実行時に検知回数が異なるところと無関係のように思われます。
@YamatoSecurity 私の開発経験が短いなりの提案ですが、並列化のバグということもあり、修正まで時間がかかりそうなので、一旦revertっぽく元に戻して、修正版をリリースするのはいかがでしょうか？ その方が品質が保たれて良さそうです。
@kazuminn pull-requestからrevertをかけようとしましたが、他修正が入っているため、Githubのpull-requestページからでは対応ができないようでした。 ブランチを切って手作業で修正してください。
I have same issue too.
IMHO, because the operation ↓ is not atomic, it's seem to cause a race condition. https://github.com/Yamato-Security/hayabusa/blob/v1.4.3/src/detections/message.rs#L115-L123
For example, if the threads are executed in the following order, detect_info will be lost?
- MESSAGES is empty.
- Thread-1 MESSAGES.get_mut(timeA) return None.
- Thread-2 MESSAGES.get_mut(timeA) return None.
- Thread-1 insert detect_info_1 with new vector.
- Thread-2 insert detect_info_2 with new vector. <- I think detect_info_1 will be lost at this timing
I created a unit test as follow, https://github.com/fukusuket/hayabusa/commit/09a146666c12ee91a1de07cb0d155ae2f80f9be4 then the test failed 1-2 times out of 10 on my Win10(8Core/16GB RAM) and M1 Mac(8Core/8GB RAM).
If you have already investigated(or my misunderstanding), please ignore this comment🚀
@fukusuket Thank you so much for looking into this for us and for the unit test! I thought it was due to a race condition due to the parallel processing but we didn't know for sure. Do you have any ideas of how to fix it? If we can't fix it soon, we plan on reverting back to how we did things before before the next 1.5.0 release so that we don't miss any events and then add back the parallel processing when it is stable.
Thank you for reply😀
Do you have any ideas of how to fix it?
I tried to fix it as follows. By using a Mutex lock(similar to version 1.4.1), prevent the race condition.
- https://github.com/fukusuket/hayabusa/commit/6bac39264da614d5f230a4caf29540fe47e393d3
And I just tested it with the following and it seems to work fine.
- Race condition reproduction unit test not failed.(Even if I run it more than 10 times)
- Run following command 3 times and got same detection results.
-
./hayabusa -d hayabusa-sample-evtx -o out.csv - (I haven't compare the performance, but the speed will be slower due to the mutex lock)
-
I've only briefly tested it so far, so I'd like to send a pull request when testing is complete.
Thank you so much! That helps us out a bunch! Please send us a pull request when you are ready. I will be happy to help test it out.
@fukusuket Thank you for your comment and test case. I will be happy to help test it.
@YamatoSecurity The problem in this case was to speed up the process by excluding Mutex. I would suggest checking to see if the time has changed significantly since v1.4.1, just to be sure.
今回のfukusuketの修正ですが、この状態になると無理にDashMapを使う理由があまりないかもしれません。(MutexでロックしているのでDashMapを使うことで想定している複数同時処理が行われない)
fukusuketが書いてもらったtestは非常に助かるので、以下のような方針で対応するのはいかがでしょうか。
- v1.4.1. とfukusuketの修正分を比較して処理時間でv1.4.1の方が早い場合 処理時間でDashMapの方が処理時間が悪化した場合は一旦fukusuketのpull requestを入れた後に処理部分をv1.4.1に戻す -fukusuketの修正分が処理時間がv1.4.1より早い場合 fukusuketの pull requestを入れて終了
@hitenkoku Thank you for review!
今回のfukusuketの修正ですが、この状態になると無理にDashMapを使う理由があまりないかもしれません。
That’s true,
If I can change the implementation(Dashmap to hashbrown::HashMap) and there seems to be no problem, I will send a pull request with the hashbrown::HashMap version?
Which implementation(Dashmap or HashMap) is better for fix this issue?
@fukusuket
Thank you for your comment.
I think that hashbrown::HashMap is better rather than Dashmap. DashMap is slow in this case Because DashMap do an unnecessary lock to process parallel.
I think a BtreeMap is better than a HashMap. With BtreeMap, you can also parallelize the alignment of data. Even with a HashMap, it is possible if you align it every time you insert, but you will not know which one is faster until you experiment with it.
ちょっと根本的なDashMapの原因について、わからなかったので、Rust-jpの方で質問しましたが、わかったので、DashMapいけそうなので、ちょっと実装してみて、確認してみようと思います。 https://rust-lang-jp.zulipchat.com/#narrow/stream/124300-questions/topic/DashMap.E3.81.AE.E6.80.AA.E3.81.97.E3.81.84.E6.8C.99.E5.8B.95/near/293088218
Thank you for comment ^^
I test above entry(event_time).or_default(); impl, then race condition reproduction unit test never failed.(Even if I run it more than 30 times).
@fukusuket san. It's a good feeling. If you like, would you like to write the PR? We'll support you.