🎉

Snowflake Event Table と Logging と Tracing 〜 Snowflake Scripting 編

がく@ちゅらデータエンジニアです。

いかんいかん、ちゃんと記事を書くぞ!って言ってたのに、あっという間に日が経っていて、タイムリープしたのかな?うん、そうだ、そうに違いない!なんて思ってます。てへぺろ(死語

概要

2023年5月のアップデートでPreviewになった機能に気になる機能がありました。
※↑が公開されてすぐ書こうとしたけど、ついつい遅れてしまった・・・・

https://docs.snowflake.com/release-notes/2023-05#logging-and-tracing-in-procedures-and-functions-preview

以前、

https://datumstudio.jp/blog/0130_snowflake_scripting_using/

こんな記事を書いてみた際に、「デバッグみたいなことがしたい」なんて書きました。
その際の方法は、

  1. 変数:log_array を array 型で宣言
  2. 何らかのデバッグポイントで、メッセージ文字列を追加 ⇨ 
    log_array := array_append(:log_array,'[CHECK1 OK] ‘ || :check_flg);
  3. 最後に log_array をリターン
  4. ストアドプロシージャを実行したら、結果としてメッセージ文字列の配列が表示

こんな流れを紹介していました。

が、あたらにPreviweになった機能では、Event Table という機能を使って実現をしています。こちらについて、検証をしてみたいと思います。

やりたいこと

  1. Event Tableを作る
  2. Accountに紐付ける
  3. Loggingしてみる
  4. (Tracingは割愛、Loggingと似てるし)
  5. 例外が起きた時の挙動確認
  6. ERRORが発生したときに、イベントをキャッチできるか試してみる

https://docs.snowflake.com/developer-guide/logging-tracing/logging-tracing-overview

を参考に、Get Started をやっていきます。

Event Tableを設定する

https://docs.snowflake.com/developer-guide/logging-tracing/event-table-setting-up

Event Table とは

  • ログ・エントリやトレース・イベントを補足するためのテーブル
  • イベントテーブルをAccountに紐付けると、そこにログ・エントリを取り込んだり、イベントをトレースできるようになる
  • イベントテーブルは、アカウントに1つのみ紐付けられる
    • ↑を「アクティブイベントテーブル」という
  • Log4Jとかみたいに、ログのレベル(CRITとかWARNとかINFOとか)を設定できる
  • ストアドプロシージャ、UDF、UDTFで生成されたログやイベントが、アクティブイベントテーブルに格納される

Event Table を作成する

Event Tableを作ってみる。

CREATE EVENT TABLE gaku_events;

※一般ロールで作成可能。(SYSADMINやACCOUNTADMINである必要はなさそう)

Event Table を Accountに紐付ける

アカウントに紐づけていきましょう。
念のため、すでにEvent  Tableが設定されていないか、確認しましょう。

SHOW PARAMETERS LIKE 'event_table' IN ACCOUNT;

設定されていないようなので、アカウントに紐づけてみます。

ALTER ACCOUNT SET EVENT_TABLE = my_database.public.gaku_events;
key value default level description type
EVENT_TABLE gaku_training_db.public.gaku_events (No value) ACCOUNT Event destination for the given target. STRING

アカウントに紐づけてみました。

ログイベントとトレースイベントのレベルを設定する

https://docs.snowflake.com/developer-guide/logging-tracing/logging-log-level

ログレベルは

  • TRACE
  • DEBUG
  • INFO
  • WARN
  • ERROR
  • FATAL
  • OFF ( Default )

とあるので、log4jとかと一緒かな ( TRACE はないけど)

オブジェクトのログレベルの設定

ちなみに、このLOG_LEVELを設定しないと、ストアド内などでログを出しても出力されませんので注意が必要です(それでハマってた同僚がいます(ニコニコ

設定できるのは

  • ストアドプロシージャ
  • UDF、UDTF
  • ストアドプロシージャやUDFを含む、データベース または スキーマ

ログレベルを設定するには、「MODIFY LOG LEVELグローバル権限」「LOG_LEVELを設定するオブジェクト(ストアド、UDF、UDTF、スキーマ、データベース)に対するMODIFY権限」
⇨ まぁ、ACCOUNTADMINがあれば出来そうではある

実際にオブジェクトにLOG_LEVELを設定するには、

-- Set the log levels on a database and UDF.
ALTER DATABASE db1 SET LOG_LEVEL = ERROR;
ALTER FUNCTION f1(int) SET LOG_LEVEL = WARN;

ログメッセージの出力

まずは、アカウントレベルでLOG_LEVELを設定してみます。

ALTER SESSION SET LOG_LEVEL = INFO;
CREATE OR REPLACE PROCEDURE log_output ()
RETURNS VARCHAR NOT NULL
LANGUAGE SQL
AS
$$
BEGIN
    SYSTEM$LOG_TRACE('Trace message');
    SYSTEM$LOG_DEBUG('Debug message');
    SYSTEM$LOG_INFO('Information-level message');
    SYSTEM$LOG_WARN('Warning message');
    SYSTEM$LOG_ERROR('Error message');
    SYSTEM$LOG_FATAL('Fatal message');
  RETURN 'success';
END;
$$
;

実行すると

call log_output ();
select * from gaku_training_db.public.gaku_events;

すぐには反映されませんね、10秒ぐらい立つと反映されますね

LOG_LEVELをACCOUNTレベルで「INFO」にしてるので、4行
INFO、WARN、ERROR、FATAL がEVENT TABLEにログ出力が書き出されます

ACCOUNT LEVELでの設定をOFFにします

ALTER SESSION UNSET LOG_LEVEL;

この時点で、

call log_output ();

ってやってもログに書かれません。

上記のFUNCTIONに

ALTER PROCEDURE log_output () SET LOG_LEVEL = WARN;

これで、WARN、ERROR、FATALの3行が記載されました

select * from gaku_training_db.public.gaku_events;

Event Table の変更をキャッチするのにSTREAM・・・・

ちなみに、ログに追記された情報を追尾するSTREAMを設定しようとしたんですが・・・・

CREATE  OR REPLACE  STREAM gaku_training_db.public.gaku_events_stream on table gaku_training_db.public.gaku_events;

STREAM作成できました

select * from gaku_training_db.public.gaku_events_stream;

ちゃんと追加されてました!
TASKと組み合わせて、ERRORが発生した場合に、何らかの処理をする事ができそう!

Exceptionの場合にも書き出されるか試してみる

CREATE OR REPLACE PROCEDURE log_output (exception_flag boolean)
RETURNS number NOT NULL
LANGUAGE SQL
AS
$$
DECLARE
  my_exception EXCEPTION (-20002, 'Raised MY_EXCEPTION.');
BEGIN
    SYSTEM$LOG_TRACE('Trace message');
    SYSTEM$LOG_DEBUG('Debug message');
    SYSTEM$LOG_INFO('Information-level message');
    SYSTEM$LOG_WARN('Warning message');
    SYSTEM$LOG_ERROR('Error message');
    SYSTEM$LOG_FATAL('Fatal message');
  LET counter := 0;
  LET should_raise_exception := exception_flag;
  IF (should_raise_exception) THEN
    RAISE my_exception;
  END IF;
  counter := counter + 1;
  RETURN counter;

EXCEPTION
    WHEN my_exception THEN
        SYSTEM$LOG_ERROR('my_exception. sqlcode = ' || sqlcode || ' sqlerrm = ' || sqlerrm || ' sqlstate = ' || sqlstate);
        RETURN OBJECT_CONSTRUCT('Error type', 'MY_EXCEPTION',
                            'SQLCODE', sqlcode,
                            'SQLERRM', sqlerrm,
                            'SQLSTATE', sqlstate);
    WHEN OTHER THEN
        SYSTEM$LOG_ERROR('other exception. sqlcode = ' || sqlcode || ' sqlerrm = ' || sqlerrm || ' sqlstate = ' || sqlstate);
        RETURN OBJECT_CONSTRUCT('Error type', 'Other error',
                            'SQLCODE', sqlcode,
                            'SQLERRM', sqlerrm,
                            'SQLSTATE', sqlstate);
    
END;
$$
;

引数が増えたので

ALTER PROCEDURE log_output (boolean) SET LOG_LEVEL = WARN;

と設定

call log_output(false);

call log_output(true); -- こちらはException内がログに書かれます


WARN、ERROR、FATALが出力されて、
ERROR(Exception)が出力されました

※Event Tableへの書き出し、1分とかかかるようになってたので、即時取得は、現時点では難しいかも

ちゅらデータ株式会社

Discussion