Help us understand the problem. What is going on with this article?

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を使うとできる2つのフィールド、この2つのフィールドをとりあえず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":"admin@hildegardsfarm.com","method":"USER","method_parameter":"admin@hildegardsfarm.com","reply_code":331,"reply_content":"User admin@hildegardsfarm.com 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

qiita1.png
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時間なので、差分は秒単位。

2つの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

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

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()ifsearchmatchstartswithendswithと同じように検索している。
count()は単にログにSTORQUITがあればいいだけなので、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は素直にstreamstatstime_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.conftransactionで扱えるイベント数とか制限がある。

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が必要だった! :astonished:

まとめ

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

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を使って遅いなと思ったらstatsstreamstatsを使ってみてください。
なんとかなります。

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

それでは。

toshikawa
Splunkでいろいろやっています。 Splunk AnswersやQiitaでSplunkについていろいろ書いています。
https://community.splunk.com/t5/user/viewprofilepage/user-id/184221
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away