Transactionあれこれ

結局小ネタになってしまいましたが、箸休めで。

趣旨

transactionは便利。でも重い。
splunkから出している資料をみても、ここの
27ページ　にtransaction使うならstats使ってと書いてある。
ということで、transactionを使わないでもなんとかできることをやってみようと思う。
あとはtransactionのあれこれ。

#durationとeventcount

Additionally, the transaction command adds two fields to the raw events, duration and eventcount.

transactionを使うとできる２つのフィールド、この２つのフィールドをとりあえずtransactionを使わずに出してみる。

SPL

index=botsv2 sourcetype=stream:ftp
| transaction flow_id
| head 1

botsv2のデータをもとにFTPのセッションを纏めてみた。結果は次の通り。

{"endtime":"2017-08-26T06:45:34.479025Z","timestamp":"2017-08-26T06:45:34.479025Z","bytes":266,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":0,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":266,"reply_time":0,"response_time":0,"time_taken":0,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","greeting":"--------- Welcome to Pure-FTPd [privsep] [TLS] ----------","reply_code":220,"reply_content":"--------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 4 of 500 allowed.\r\n220-Local time is now 13:19. Server port: 21.\r\n220-This is a private system - No anonymous login\r\nYou will be disconnected after 15 minutes of inactivity.\r\n","protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:34.528205Z","timestamp":"2017-08-26T06:45:34.479460Z","bytes":88,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":31,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":57,"reply_time":48745,"response_time":0,"time_taken":48745,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","login":"[e-mail]","method":"USER","method_parameter":"[e-mail]","reply_code":331,"reply_content":"User [e-mail] OK. Password required\r\n","protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:34.605173Z","timestamp":"2017-08-26T06:45:34.528457Z","bytes":111,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":28,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":83,"reply_time":76716,"response_time":0,"time_taken":76716,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","method":"PASS","method_parameter":"I_love_daves_basement","reply_code":230,"reply_content":"Your bandwidth usage is restricted\r\nOK. Current restricted directory is /\r\n","protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:34.655658Z","timestamp":"2017-08-26T06:45:34.605653Z","bytes":50,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":12,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":38,"reply_time":50005,"response_time":0,"time_taken":50005,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","method":"CWD","method_parameter":"upload","reply_code":250,"reply_content":"OK. Current directory is /upload\r\n","protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:34.708732Z","timestamp":"2017-08-26T06:45:34.656122Z","bytes":38,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":8,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":30,"reply_time":52610,"response_time":0,"time_taken":52610,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","method":"TYPE","method_parameter":"I","reply_code":200,"reply_content":"TYPE is now 8-bit binary\r\n","protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:34.755834Z","timestamp":"2017-08-26T06:45:34.709624Z","bytes":53,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":24,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":29,"reply_time":46210,"response_time":0,"time_taken":46210,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","data_port":59680,"method":"PORT","method_parameter":"10,0,2,107,233,32","reply_code":200,"reply_content":"PORT command successful\r\n","protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:34.958725Z","timestamp":"2017-08-26T06:45:34.756085Z","bytes":121,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":25,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":96,"reply_time":91438,"response_time":111202,"time_taken":202640,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","filename":"topsecretyeast.pdf","loadway":"Upload","method":"STOR","method_parameter":"topsecretyeast.pdf","offset":0,"reply_code":[150,226],"reply_content":"Connecting to port 46991\r\nError during read from data connection\r\nTransfer aborted\r\n","transfer_duration":111202,"protocol_stack":"ip:tcp:ftp"}
{"endtime":"2017-08-26T06:45:35.004984Z","timestamp":"2017-08-26T06:45:34.959198Z","bytes":73,"src_ip":"10.0.2.107","src_mac":"00:0C:29:6F:D0:2F","src_port":59679,"bytes_in":6,"request_time":0,"dest_ip":"160.153.91.7","dest_mac":"58:49:3B:8A:8B:12","dest_port":21,"bytes_out":67,"reply_time":45786,"response_time":0,"time_taken":45786,"transport":"tcp","flow_id":"61c34c81-406f-4027-a911-856c7b6d3825","method":"QUIT","reply_code":221,"reply_content":"Goodbye. You uploaded 0 and downloaded 0 kbytes.\r\nLogout.\r\n","protocol_stack":"ip:tcp:ftp"}

結果は

duration	eventcount
0.525	8

##duration

SPL

index=botsv2 sourcetype=stream:ftp
| eventstats range(_time) as duration count(_raw) as eventcount by flow_id
| head 1

eventstatsではなく、statsでも結果は同じ。

duration	eventcount
0.525	8

eval - splunk docs

**range()**については

range()
Returns the difference between the max and min values of the field X. The values of field X must be numeric.

ということで、差分を出してくれる。_timeはepoch time、UNIX時間なので、差分は秒単位。

２つのjobの時間を確認すると
transaction: This search has completed and has returned 1 件の結果 by scanning 1,490 件のイベント in 1.599 seconds

eventstats: This search has completed and has returned 1 件の結果 by scanning 1,490 件のイベント in 1.684 seconds

この企画を真っ向から否定されている。イベント数が少ないとこんなもんですね。

#transactionのオプション
##keepevicted
transaction使う時ちょっとこまるのが、たまにイベントにフィールドがない時。
普通にやると、そのログは検索結果から出なくなってしまう。
transactionした後ログの数が違うなって時はkeepevicted=trueにしてあげるとtransactionの引数であるフィールドがないログも保持してくれる。

##startswithとendswith
ログの文字やevalで評価した場所からまとめてくれる便利なオプション
これも、statsでやってみる。

SPL

index=botsv2 sourcetype=stream:ftp
| stats latest(_time) as _time range(eval(if(searchmatch("STOR") OR searchmatch("QUIT"),_time,NULL))) as duration count(eval(searchmatch("STOR") OR searchmatch("QUIT"))) as eventcount by flow_id
| sort - _time
| head 1

flow_id	_time	duration	eventcount
61c34c81-406f-4027-a911-856c7b6d3825	2017/08/26 15:45:35.004	0.046	2

最初のlatest()は単に一番最後のログにしたかったので。
range()はifとsearchmatchでstartswithとendswithと同じように検索している。
count()は単にログに_STOR_と_QUIT_があればいいだけなので、ifはいらない。

なお、Error in 'stats' command: You must specify a rename for the aggregation specifier on the dynamically evaluated field 'count
のエラーが出た時はASでフィールド名をつけてねということ。

SPL

index=botsv2 earliest=1 sourcetype=stream:ftp (method="STOR" OR method="QUIT")
 | stats dc(method) AS count values(method) AS status BY flow_id
 | where count=1

このクエリーは少し違って、STORだけのflowを追いかけている。transactionの使い方として状態遷移を確認(statusとか)するといったこともあるけど、そんな時にこれを使う。

##maxspanとmaxpause
どの期間のイベントをまとめるのかがmaxspan、この時間以上離れたら別のイベントとしてまとめるのがmaxpause

maxspanは素直にstreamstatsの_time_window_で代替が可能。
maxpauseはちょっと代替えが思いつきません。
binを使ってログを時間単位でまとめられるので、そちらでできるかな？
どんなログで使うんだろう？

#transactionの制限
https://answers.splunk.com/answers/823710/are-there-any-restrictions-for-the-transaction-com.html
で回答したとき調べてみた

limits.conf

[transactions]
maxopentxn = <integer>
* Specifies the maximum number of not yet closed transactions to keep in the
  open pool before starting to evict transactions.
* Default: 5000

maxopenevents = <integer>
* Specifies the maximum number of events (which are) part of open transactions
  before transaction eviction starts happening, using LRU policy.
* Default: 100000 

limits.confにtransactionで扱えるイベント数とか制限がある。

transaction_max.spl

 | makeresults count=1000000
 | streamstats count as A
 | eval A=A % 2
 | streamstats count as B
 | transaction A

の結果は1000しかないのも、_limits.conf_の制限

search.log

05-17-2020 XX:XX:XX.942 INFO  NewTransam - evicted=0, closed=1000, event_count=1000000, candidate_events=999000, comparison_count=999998

ということで、transactionの結果が省略されたことは_search.log_に出ている。
ジョブの表示には出ない。

#小ネタ
2020/12/30追記。Slackでやってみたのが面白かったので

結果なし

| makeresults count=100
| eval version = random() % 10 .".". random() % 10
| fields - _time
| transaction version

結果あり

| makeresults count=100
| eval version = random() % 10 .".". random() % 10
| transaction version

transctionするには_timeが必要だった！

#まとめ
とりとめもなくなってしまった。

SPL

index=botsv2 sourcetype=stream:http earliest=1
| reverse
| transaction flow_id keepevicted=true

This search has completed and has returned 1,000 件の結果 by scanning 104,209 件のイベント in 104.882 seconds

SPL

index=botsv2 sourcetype=stream:http earliest=1
| reverse
| stats first(_time) as _time values(_raw) as _raw range(_time) as duration count as linecount by flow_id

This search has completed and has returned 26,376 件の結果 by scanning 104,209 件のイベント in 49.432 seconds

とりあえず形だけ一緒にしてみた検索だとこんなに検索時間に差がでます。
transactionを使って遅いなと思ったらstatsやstreamstatsを使ってみてください。
なんとかなります。

なんとかならなそうなら、Splunk AnswerかGOJAS - Go Japan Splunk User Groupに質問を投げてみてください。
splunk answerの場合は_japanese_のタグをつけてもらえれば、日本語でＯＫです。

それでは。