Transactionあれこれ

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

# 趣旨
`transaction`は便利。でも重い。
splunkから出している資料をみても、ここの
[27ページ](https://www.slideshare.net/takashikomatsubara50/how-search-works-tsidxterm)　に`transaction`使うなら`stats`使ってと書いてある。
ということで、`transaction`を使わないでもなんとかできることをやってみようと思う。
あとは`transaction`のあれこれ。

#durationとeventcount
>Additionally, the transaction command adds two fields to the raw events, `duration` and `eventcount`. 

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

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

[botsv2](https://github.com/splunk/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
```splunk:SPL
index=botsv2 sourcetype=stream:ftp
| eventstats range(_time) as duration count(_raw) as eventcount by flow_id
| head 1
```

![qiita1.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/130729/236aa9b5-8b5a-36fc-97a3-1d76fbcd55b6.png)
`eventstats`ではなく、`stats`でも結果は同じ。

|duration|eventcount|
|--:|--:|
|0.525|8|

[eval - splunk docs](https://docs.splunk.com/Documentation/Splunk/8.0.0/SearchReference/Aggregatefunctions)

**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時間](https://ja.wikipedia.org/wiki/UNIX%E6%99%82%E9%96%93)なので、差分は秒単位。


２つの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`でやってみる。

```Splunk: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`でフィールド名をつけてねということ。

```Splunk: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
で回答したとき調べてみた

```configuration: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](https://docs.splunk.com/Documentation/Splunk/latest/Admin/Limitsconf#.5Btransactions.5D)に`transaction`で扱えるイベント数とか制限がある。

```sql:transaction_max.spl
 | makeresults count=1000000
 | streamstats count as A
 | eval A=A % 2
 | streamstats count as B
 | transaction A
```
の結果は1000しかないのも、_limits.conf_の制限

```console: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でやってみたのが面白かったので

```javascript:結果なし
| makeresults count=100
| eval version = random() % 10 .".". random() % 10
| fields - _time
| transaction version
```

```javascript:結果あり
| makeresults count=100
| eval version = random() % 10 .".". random() % 10
| transaction version
```

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

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

```Splunk: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

```Splunk: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](https://answers.splunk.com/index.html)か[GOJAS - Go Japan Splunk User Group](https://gojas.slack.com)に質問を投げてみてください。
splunk answerの場合は_japanese_のタグをつけてもらえれば、日本語でＯＫです。

それでは。