SQLを用いたログ解析

# 前書き
仕事の関係で膨大なログを解析することがあった。とにかく量は大きいのでbigdata基盤の上に載せて色々解析を行なった。二度と必要ないと思ったら、ちょうど一年後またほぼ同じことをやる必要がある。一年前、色々やったことを記録しないことは後悔した。今回こそやったことの記録に残し、少しでも役に立てば嬉しいと思う。

簡単のために、サンプルにおいてtime_stampは整数を使う。また、説明の目的でsqlの効率を考慮していないい。よりシンプルで、より早いsqlにする余地はまだたくさんある。


# 環境
hadoop基盤の上でprestoクライアントを用いた

# ログからセッション作成
まず、「ログ解析」といいながら、大したことをやっていなかった。主に様々ログからユーザのセッション（開始、終了および付属した情報）を作ることだった。

セッションの開始・終了の時刻だけではなく他のセッション情報（IPアドレスなど）も必要な場合がある（今回の例では含まれていない）

量が多いので手動で自分の端末できる範囲を超えるため、弊社を持っているBigData分析基盤に入れ、SQL
を用い解析を行なった。ここで考えたこと、やったことを簡単にまとめる。

今回の経験で、セッションを作成するため、以下の手法で有効でることがわかった。

2ステップがある：
　1. マーキング（Marking）：ターゲットのログ（開始・終了など）のシグニチャーを用いマーキングする
　2. セレクション（Selection）：マーキングした情報を適切に選択しセッションを作成する
 

## マーキング
ログ種類によって色々マーキング方法がある。この段階では、どのユーザのログや、セッションIDなどを考える必要ない。有効なシグネチャーを探せるかどうかポイント

また、ログ種類によって、セッションの開始、終了のそれぞれマーキングできるものもあれば、セッション開始しかないものもある

> ログインするときに認証とか必要な場合が多いので、ほとんどの場合、該当するログがある。逆に、ログアウトする際、該当するログがない場合が多く、代わりにタイム・アウトログがある場合も多い。

マーキングする方法も色々あるが、ログ情報から文字列で比較し、「0」, 「1」の値でマーキングするのは便利である。

## セレックション
セッション開始・終了どちらも正しく取れるログにおいて、開始と終了を同じ行にまとめればセッション情報を比較的に簡単に作れる（例1）

しかし、どちらかがしかが取ればい場合やどちらも取れない場合も珍しくない。その場合、logoffしかない場合、あるユーザのログがあるところから次に `logoff`までの全てログは同じセッションと考える必要がある。

ここでSQLのwindows関数を活用する。イメージは、順次にログをチェックし、上からマーキングしたflagの値を合算していく。従って、マーキングされたところで境界線として値が増え続け、同じ値にならない。同じ合算結果は同じ「ブロック」となり、そのブロックの最小、最大のタイムスタムはそれぞれセッションの開始・終了時刻になる

#### セレクション・ロジック
実際として、ロジックはもうちょっと考える必要がある。例えば、loginを基づく方法であれば、合算していくだけで良いであるが、logoutを含めたセッションを作る時に、合算するときに、その行の値を除く必要がる（使ってるSQLによって多少表現が違うか、一つ簡単な方法は「その行の値を引く」ことである）


## 例
上のベスト・プラティスを示すため、2つの例を紹介する。

### 例１：login/logoff両方ともある場合
以下のログがあるとする

   time_stamp   | user |     msg
----------------+------+-------------
 20210624000000 | xxx  | login: xxx
 20210624000005 | yyy  | login: yyy
 20210624000010 | xxx  | other xxx
 20210624000012 | yyy  | logoff: yyy
 20210624000020 | xxx  | logoff: xxx
 20210624000025 | xxx  | login: xxx
 20210624000030 | xxx  | logoff: xxx

まず、マーキングを行う。

```sql:tmp02
select *,
if (regexp_like(msg,'login:'),1,0) login_flag,
if (regexp_like(msg,'logoff:'),1,0) logoff_flag
from tmp01
```

マーキングの結果はこのようになった

   time_stamp   | user |     msg     | login_flag | logoff_flag
----------------+------+-------------+------------+-------------
 20210624000000 | xxx  | login: xxx  |          1 |           0
 20210624000005 | yyy  | login: yyy  |          1 |           0
 20210624000010 | xxx  | other xxx   |          0 |           0
 20210624000012 | yyy  | logoff: yyy |          0 |           1
 20210624000020 | xxx  | logoff: xxx |          0 |           1
 20210624000025 | xxx  | login: xxx  |          1 |           0
 20210624000030 | xxx  | logoff: xxx |          0 |           1

次に、セッション開始、終了の情報だたけをみる。すると、あるユーザの開始・終了のログに対して、loginの次はlogoffになる。その情報を用い最終的にセッション情報をまとめる。

```sql:tmp03
select user,login_flag,time_stamp session_start, lead(time_stamp) over (partition by user order by time_stamp) session_stop
from tmp02
where not (login_flag=0 and logoff_flag=0)
```
ここでwindow関数 LEADを用い、次の行の値（loginのログからみると logoffの時間）を使う。

実行結果はこのようになった

 user | login_flag | session_start  |  session_stop
------+------------+----------------+----------------
 xxx  |          1 | 20210624000000 | 20210624000020
 yyy  |          1 | 20210624000005 | 20210624000012
 yyy  |          0 | 20210624000012 |           NULL
 xxx  |          0 | 20210624000020 | 20210624000025
 xxx  |          1 | 20210624000025 | 20210624000030
 xxx  |          0 | 20210624000030 |           NULL

ここで、`login_flag=1` のとこらだけ選択すれば良い

```sql:
select user,session_start,session_stop 
from tmp03
where login_flag=1
```
これによって最終の結果はこのように得られた

```
 user | session_start  |  session_stop
------+----------------+----------------
 xxx  | 20210624000000 | 20210624000020
 xxx  | 20210624000025 | 20210624000030
 yyy  | 20210624000005 | 20210624000012
```


### 例２：logoffしかない場合

この例では、例1と違い、ユーザのログインのログはあるが、シグネチャーを確定できないと仮定する。あるユーザのセッションはそのユーザのログがあるところから、logoutログがあるところまで（logoutログのtimestamp）とする

   time_stamp   | user |        msg
----------------+------+--------------------
 20210624000000 | xxx  | login: xxx
 20210624000005 | yyy  | login for user yyy
 20210624000010 | xxx  | other xxx
 20210624000012 | yyy  | logoff: yyy
 20210624000020 | xxx  | logoff: xxx
 20210624000025 | xxx  | login with xxx
 20210624000030 | xxx  | logoff: xxx



まず、正規表現を用いマーキングを行う。

```sql:
select *,
if (regexp_like(msg,'logoff:'),1,0) logoff_flag
from tmp01 
order by time_stamp;
```

マーキングした結果はこのようになった

   time_stamp   | user |        msg         | logoff_flag
----------------+------+--------------------+-------------
 20210624000000 | xxx  | login: xxx         |           0
 20210624000005 | yyy  | login for user yyy |           0
 20210624000010 | xxx  | other xxx          |           0
 20210624000012 | yyy  | logoff: yyy        |           1
 20210624000020 | xxx  | logoff: xxx        |           1
 20210624000025 | xxx  | login with xxx     |           0
 20210624000030 | xxx  | logoff: xxx        |           1


次に、windows関数で、userごとで関係なログをまとめる（ブロック化）

```sql:
select *,
sum(logoff_flag) over (partition by user order by time_stamp) - logoff_flag session_id
from tmp03
order by time_stamp;
```

ここで、`- logoff_flag session_id` は [ここ](#詳細選択) で説明したことを実現するため
`session_id` 計算した結果はこのようになった


   time_stamp   | user |        msg         | logoff_flag | session_id
----------------+------+--------------------+-------------+------------
 20210624000000 | xxx  | login: xxx         |           0 |          0
 20210624000005 | yyy  | login for user yyy |           0 |          0
 20210624000010 | xxx  | other xxx          |           0 |          0
 20210624000012 | yyy  | logoff: yyy        |           1 |          0
 20210624000020 | xxx  | logoff: xxx        |           1 |          0
 20210624000025 | xxx  | login with xxx     |           0 |          1
 20210624000030 | xxx  | logoff: xxx        |           1 |          1

ここで同じ `user` のログのセッションに対して、同じ `session_id`をつけることができた。
__注意：違う`user`だと同じ `session_id` はありえる！__

最後に、セッション情報から、開始（`time_stamp`のmin値）、終了（`time_stamp`のmax値）をまとめる。

```sql
select 
user,session_id,min(time_stamp) session_start,max(time_stamp) session_stop
from tmp03
group by user,session_id
order by user,session_id;
```

結果はこのようになった

 user | session_id | session_start  |  session_stop
------+------------+----------------+----------------
 xxx  |          0 | 20210624000000 | 20210624000020
 xxx  |          1 | 20210624000025 | 20210624000030
 yyy  |          0 | 20210624000005 | 20210624000012


# 付録
使ったsql（サンプルデータ作成を含めた）

##例1のsql
```sql
with tmp01 as(
select 
       20210624000000 time_stamp, 'xxx' as user, 'login: xxx' as msg
union
select 20210624000010, 'xxx', 'other xxx'
union
select 20210624000020, 'xxx', 'logoff: xxx'
union
select 20210624000005, 'yyy', 'login: yyy'
union 
select 20210624000012, 'yyy','logoff: yyy'
union
select 20210624000025, 'xxx', 'login: xxx'
union
select 20210624000030, 'xxx', 'logoff: xxx'
),
tmp02 as (
select *,
if (regexp_like(msg,'login:'),1,0) login_flag,
if (regexp_like(msg,'logoff:'),1,0) logoff_flag
from tmp01
),
tmp03 as (
select user,login_flag,time_stamp session_start, lead(time_stamp) over (partition by user order by time_stamp) session_stop
from tmp02
where not (login_flag=0 and logoff_flag=0)
)
select user,session_start,session_stop 
from tmp03
where login_flag=1
order by user,session_start
```

##例2のsql

```sql
with tmp01 as(
select 
       20210624000000 time_stamp, 'xxx' as user, 'login: xxx' as msg
union
select 20210624000010, 'xxx', 'other xxx'
union
select 20210624000020, 'xxx', 'logoff: xxx'
union
select 20210624000005, 'yyy', 'login for user yyy'
union 
select 20210624000012, 'yyy','logoff: yyy'
union
select 20210624000025, 'xxx', 'login with xxx'
union
select 20210624000030, 'xxx', 'logoff: xxx'
),
tmp02 as (
select *,
if (regexp_like(msg,'logoff:'),1,0) logoff_flag
from tmp01
),
tmp03 as (
select *,
sum(logoff_flag) over (partition by user order by time_stamp) - logoff_flag session_id
from tmp02
)
select 
user,session_id,min(time_stamp) session_start,max(time_stamp) session_stop
from tmp03
group by user,session_id
order by user,session_id;
```

# 他の関連記事
- [prestoとhiveで同じSQL文を使うときでハマったこと](https://qiita.com/bachng/items/0ef0ba595df3218bbdd6)