はじめに

2023年5月のアップデートでパブリックプレビューになった「Logging and Tracing in Procedures and Functions」。
ストアドプロシージャおよび UDFs で、ログメッセージとトレースデータを Event Table（新しいテーブルタイプ！）に記録できます。
Snowflake のストアドプロシージャや UDFs で実行するコードを作成する際、例えば Python の logging モジュールでログ出力を仕込んでおけば、ログファイルや notebook のセル等にログが記録されるので、ローカルな開発環境でログを確認することはできていました。しかしながら、Snowflake 上ではコード中のログ出力を記録しておく場所がなかったため、これまではログを仕込んでいても確認する術がなかったのではないかと思います。^[1]

というわけで、運用上とってもありがたそうなこの機能、簡単にですが動かしてみましたので、ここにまとめておきます。

やったこと

Logging してみる
Tracing もやってみよう
スタックトレースも欲しい
Logging の外

Logging してみる

get-started に沿って、次の手順でレッツロギング！

イベントテーブルを作成する
logger を使ったストアドプロシージャを作成
ログレベルを設定する
ストアドプロシージャを実行する

最後にログが出ていれば大☆成☆功です。やっていきましょう。

イベントテーブルを作成する

イベントテーブル my_database.my_schema.my_events を作成して、アカウントに設定します。^[2] こちらのサンプルクエリをそのまま使っていきます。

-- データベースとスキーマの準備
USE ROLE SYSADMIN;
CREATE DATABASE "MY_DATABASE";
CREATE SCHEMA "MY_DATABASE"."MY_SCHEMA";
USE SCHEMA "MY_DATABASE"."MY_SCHEMA";

-- イベントテーブル作成
CREATE OR REPLACE EVENT TABLE "MY_DATABASE"."MY_SCHEMA"."MY_EVENTS";

-- アカウントにイベントテーブルを設定
USE ROLE ACCOUNTADMIN;
ALTER ACCOUNT SET EVENT_TABLE = "MY_DATABASE"."MY_SCHEMA"."MY_EVENTS";

アカウントに設定されているイベントテーブルを確認しておきましょう。

SHOW PARAMETERS LIKE 'event_table' IN ACCOUNT;

result

+---------------+--------------------------------------------+---------+---------+------------------------------------------------------+--------+
| key           | value                                      | default | level   | description                                          | type   |
|---------------+--------------------------------------------+---------+---------+------------------------------------------------------+--------|
| EVENT_TABLE   | "MY_DATABASE"."MY_SCHEMA"."MY_EVENTS"      |         | ACCOUNT | Event destination for the given target.              | STRING |
+---------------+--------------------------------------------+---------+---------+------------------------------------------------------+--------+

作成したイベントテーブルが設定されているので、OKですね。

logging パッケージを使ったストアドプロシージャを作成

ログ出力をストアドプロシージャに仕込んでみましょう。Pythonでの実装サンプルを~~パクリ~~そのまま使用します。

USE ROLE SYSADMIN;

CREATE OR REPLACE PROCEDURE do_logging()
    RETURNS VARCHAR
    LANGUAGE PYTHON
    PACKAGES=('snowflake-snowpark-python')
    RUNTIME_VERSION=3.8
    HANDLER='do_things'
    AS 
$$
import logging

logger = logging.getLogger("python_logger")
logger.info("Logging from Python module.")

def do_things(session):
  logger.info("Logging from Python function start.")

  try:
    throw_exception()
  except Exception:
    logger.error("Logging an error from Python handler: ")
    return "ERROR"

  return "SUCCESS"

def throw_exception():
  raise Exception("Something went wrong.")
$$;

ログレベルを設定する

ログを記録するにはログレベルの設定が必要です。
ログレベルは、セッションまたはオブジェクトに対して設定することができます。いずれも未設定の場合、ログは出力されません。

例えば、セッションおよびオブジェクトに設定されたログレベルにより、使用されるログレベルは次のように決まります。

セッションの価値	オブジェクト、スキーマ、データベース、またはアカウントの値	使用されるログレベル
(unset)	WARN	WARN
DEBUG	(unset)	DEBUG
WARN	ERROR	WARN
INFO	DEBUG	DEBUG
(unset)	(unset)	OFF

（Setting Log Level > Understanding How Snowflake Determines the Effective Log Level より引用しました。詳しくは同ページをご参照ください）

というわけで、設定していきます。
ここでは、ストアドプロシージャに対してログレベルを設定します。設定の際、MODIFY LOG LEVEL 権限（セッションの場合は MODIFY SESSION LOG LEVEL ）が必要なので、SYSADMINでは不足です。

ALTER PROCEDURE do_logging() SET LOG_LEVEL = DEBUG;
-- 実行すると： Insufficient privileges to operate on  'ACCOUNT'

というわけで ACCOUNTADMIN を使っていきます。

USE ROLE ACCOUNTADMIN;
ALTER PROCEDURE do_logging() SET LOG_LEVEL = DEBUG;

ストアドプロシージャを実行する

では、ログを吐かせていきましょう。

-- 実行
USE ROLE SYSADMIN;
call do_logging();

result

+------------+
| DO_LOGGING |
+------------+
| ERROR      |
+------------+

実行したのち、数十秒ほど待ってから、ログを確認します。^[3]

-- ログ確認
SET event_table_name='MY_DATABASE.MY_SCHEMA.MY_EVENTS';
SELECT
  *
FROM
  IDENTIFIER($event_table_name)
WHERE
  SCOPE['name'] = 'python_logger'
  AND RECORD_TYPE = 'LOG';

result

+-------------------------+-------------------------+-------------------------+-------+----------+--------------------------------------------------------------+---------------------------+-------------------+-------------+----------------------------+------------------------------------+------------------------------------------+-----------+
| TIMESTAMP               | START_TIMESTAMP         | OBSERVED_TIMESTAMP      | TRACE | RESOURCE | RESOURCE_ATTRIBUTES                                          | SCOPE                     | SCOPE_ATTRIBUTES  | RECORD_TYPE | RECORD                     | RECORD_ATTRIBUTES                  | VALUE                                    | EXEMPLARS |
+-------------------------+-------------------------+-------------------------+-------+----------+--------------------------------------------------------------+---------------------------+-------------------+-------------+----------------------------+------------------------------------+------------------------------------------+-----------+
| 2023-05-25 07:47:26.071 |                         | 2023-05-25 07:47:26.071 |       |          |  {                                                           | {                         |                   | LOG         | {                          | {                                  |  "Logging from Python module."           |           |    
|                         |                         |                         |       |          |    "db.user": "<user_name>",                                 |   "name": "python_logger" |                   |             |   "severity_text": "INFO"  |   "code.filepath": "_udf_code.py", |                                          |           |
|                         |                         |                         |       |          |    "snow.database.id": 321,                                  | }                         |                   |             | }                          |   "code.function": "<module>",     |                                          |           |
|                         |                         |                         |       |          |    "snow.database.name": "MY_DATABASE",                      |                           |                   |             |                            |   "code.lineno": 5                 |                                          |           |
|                         |                         |                         |       |          |    "snow.executable.id": 2155,                               |                           |                   |             |                            | }                                  |                                          |           |
|                         |                         |                         |       |          |    "snow.executable.name": "DO_LOGGING():VARCHAR(16777216)", |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.executable.type": "PROCEDURE",                      |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.owner.id": 4,                                       |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.owner.name": "SYSADMIN",                            |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.query.id": "01ac8493-0000-eb40-0000-2c790164e482",  |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.schema.id": 664,                                    |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.schema.name": "MY_SCHEMA",                          |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.session.id": 48898225230306,                        |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.session.role.primary.id": 4,                        |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.session.role.primary.name": "SYSADMIN",             |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.user.id": 24,                                       |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.warehouse.id": 123,                                 |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "snow.warehouse.name": "<warehouse_name>",                |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |    "telemetry.sdk.language": "python"                        |                           |                   |             |                            |                                    |                                          |           |
|                         |                         |                         |       |          |  }                                                           |                           |                   |             |                            |                                    |                                          |           |
| 2023-05-25 07:47:26.143 |                         | 2023-05-25 07:47:26.143 |       |          |  (長いので省略)                                               | {                         |                   | LOG         | {                          | {                                  | "Logging from Python function start."    |           |
|                         |                         |                         |       |          |                                                              |   "name": "python_logger" |                   |             |   "severity_text": "INFO"  |   "code.filepath": "_udf_code.py", |                                          |           |
|                         |                         |                         |       |          |                                                              | }                         |                   |             | }                          |   "code.function": "do_things",    |                                          |           |
|                         |                         |                         |       |          |                                                              |                           |                   |             |                            |   "code.lineno": 8                 |                                          |           |
|                         |                         |                         |       |          |                                                              |                           |                   |             |                            | }                                  |                                          |           |
| 2023-05-25 07:47:26.143 |                         | 2023-05-25 07:47:26.143 |       |          |  (長いので省略)                                               | {                         |                   | LOG         | {                          | {                                  | "Logging an error from Python handler: " |           |
|                         |                         |                         |       |          |                                                              |   "name": "python_logger" |                   |             |   "severity_text": "ERROR" |   "code.filepath": "_udf_code.py", |                                          |           |
|                         |                         |                         |       |          |                                                              | }                         |                   |             | }                          |   "code.function": "do_things",    |                                          |           |
|                         |                         |                         |       |          |                                                              |                           |                   |             |                            |   "code.lineno": 13                |                                          |           |
|                         |                         |                         |       |          |                                                              |                           |                   |             |                            | }                                  |                                          |           |
+-------------------------+-------------------------+-------------------------+-------+----------+--------------------------------------------------------------+---------------------------+-------------------+-------------+----------------------------+------------------------------------+------------------------------------------+-----------+

設定したログレベルでメッセージが記録されていますね。ロギング大☆成☆功！

ログレベルとメッセージだけ取り出すなら、こんな感じになります。（サンプルママ）

SELECT
  RECORD['severity_text'] AS SEVERITY,
  VALUE AS MESSAGE
FROM
  IDENTIFIER($event_table_name)
WHERE
  SCOPE['name'] = 'python_logger'
  AND RECORD_TYPE = 'LOG';

result

+----------+-----------------------------------------+
| SEVERITY | MESSAGE                                 |
|----------+-----------------------------------------+
| "INFO"   | "Logging from Python module."           |
| "INFO"   | "Logging from Python function start."   |
| "ERROR"  | "Logging an error from Python handler:" |
+----------+-----------------------------------------+

Tracing もやってみよう

続けて Tracing も使ってみましょう。Getting Startedに従って進めてみます：

イベントテーブルを作成する（省略）
tracing（telemetry パッケージ）を使ったストアドプロシージャを作成
トレースレベルを設定する
ストアドプロシージャを実行する

イベントテーブルを作成する

Logging 用に作成しているので、今回は省略。

telemetry パッケージを使ったストアドプロシージャを作成

ここもサンプルコードを~~パクッて~~そのまま使っていきます。

USE ROLE SYSADMIN;
CREATE OR REPLACE PROCEDURE do_tracing()
RETURNS VARIANT
LANGUAGE PYTHON
PACKAGES=('snowflake-snowpark-python', 'snowflake-telemetry-python')
RUNTIME_VERSION=3.8
HANDLER='run'
AS $$
from snowflake import telemetry


def run(session):
  telemetry.set_span_attribute("example.proc.do_tracing", "begin")
  telemetry.add_event("event_with_attributes", {"example.key1": "value1", "example.key2": "value2"})
  return "SUCCESS"

$$;

set_span_attribute() で span データを記録し、add_event() で event データを記録していきます。詳しくは How Snowflake Represents Trace Events をご参照ください。

トレースレベルを設定する

トレースを記録するには、トレースレベルの設定が必要です。トレースの場合は MODIFY TRACE LEVEL 権限が必要ですので、こちらでも ACCOUNTADMIN を使っていきます。

USE ROLE ACCOUNTADMIN;
ALTER PROCEDURE do_tracing() SET TRACE_LEVEL = ALWAYS;

ストアドプロシージャを実行する

では、トレースさせていきましょう。

CALL do_tracing();

result

+------------+
| DO_TRACING |
+------------+
| "SUCCESS"  |
+------------+

少し待って、確認します。

SELECT
  TIMESTAMP as time,
  RESOURCE_ATTRIBUTES['snow.executable.name'] as handler_name,
  RESOURCE_ATTRIBUTES['snow.executable.type'] as handler_type,
  RECORD['name'] as event_name,
  RECORD_ATTRIBUTES as attributes
FROM
  IDENTIFIER($event_table_name)
WHERE
  RECORD_TYPE LIKE 'SPAN%'
  AND HANDLER_NAME LIKE 'DO_TRACING%';

result

+-------------------------+------------------------+--------------+-------------------------+----------------------------------------------------------+
| TIME                    | HANDLER_NAME           | HANDLER_TYPE | EVENT_NAME              | ATTRIBUTES                                               |
+-------------------------+------------------------+--------------+-------------------------+----------------------------------------------------------+
| 2023-05-26 14:20:59.228 | "DO_TRACING():VARIANT" | "PROCEDURE"  | "snow.auto_instrumented" | {                                                       |
|                         |                        |              |                          |   "example.proc.do_tracing": "begin"                    |
|                         |                        |              |                          | }                                                       |
| 2023-05-26 14:20:59.226 | "DO_TRACING():VARIANT" | "PROCEDURE"  | "event_with_attributes"  | {                                                       |
|                         |                        |              |                          |   "example.key1": "value1",                             |
|                         |                        |              |                          |   "example.key2": "value2"                              |
|                         |                        |              |                          | }                                                       |
+-------------------------+------------------------+--------------+-------------------------+----------------------------------------------------------+

span と event がそれぞれ記録されているので、こちらも大☆成☆功です。

スタックトレースも欲しい

さて、先の do_logger() では、エラーメッセージのみ記録されていました。実際に運用しているストアドプロシージャや UDFs でエラーが出た時のことを考えると、スタックトレースの内容も欲しいところです。
そこで error() ではなく exception() を呼んでみましょう。

CREATE OR REPLACE PROCEDURE do_logger_exception()
    RETURNS VARCHAR
    LANGUAGE PYTHON
    RUNTIME_VERSION='3.8'
    PACKAGES = ('snowflake-snowpark-python')
    HANDLER = 'main'
    AS
$$
import logging


logger = logging.getLogger('do_logger_exception')
logger.info("Logging from Python module.")

def main(session):
    ret = 'Succeeded'

    try:
        throw_exception("error!")
    except:
        logger.exception("なんか try の中で例外投げられたぽいっすよ.") 
        ret = 'Failed'
    
    return ret

def throw_exception(msg: str):
    raise Exception(msg)

$$;

USE ROLE ACCOUNTADMIN;
ALTER PROCEDURE do_logger_exception() SET LOG_LEVEL = INFO;

ちょっと待ってから、イベントテーブルを見てみます。RECORD_ATTRIBUTES の中身を詳しく見てみましょう。詳細はEvent table columnsをご参照ください。

SELECT
  RECORD['severity_text'] AS SEVERITY,
  VALUE AS MESSAGE,
  RECORD_ATTRIBUTES['exception.message'] AS EXCEPTION_MESSAGE,
  SPLIT(RECORD_ATTRIBUTES['exception.stacktrace'], '\n') AS EXCEPTION_STACKTRACE,
  RECORD_ATTRIBUTES['code.filepath'] AS CODE_FILEPATH,
  RECORD_ATTRIBUTES['code.function'] AS CODE_FUNCTION,
  RECORD_ATTRIBUTES['code.lineno'] AS CODE_LINENO,
  RECORD_ATTRIBUTES['code.namespace'] AS CODE_NAMESPACE,
  RECORD_ATTRIBUTES['thread.id'] AS THREAD_ID,
  RECORD_ATTRIBUTES['thread.name'] AS THREAD_NAME
FROM
  IDENTIFIER($event_table_name)
WHERE
  SCOPE['name'] = 'do_logger_exception'
  AND RECORD_TYPE = 'LOG';

result

+----------+----------------------------------------------+-------------------+-----------------------------------------------------------+---------------+---------------+-------------+----------------+-----------+-------------+
| SEVERITY | MESSAGE                                      | EXCEPTION_MESSAGE | EXCEPTION_STACKTRACE                                      | CODE_FILEPATH | CODE_FUNCTION | CODE_LINENO | CODE_NAMESPACE | THREAD_ID | THREAD_NAME |
+----------+----------------------------------------------+-------------------+-----------------------------------------------------------+---------------+---------------+-------------+----------------+-----------+-------------+
| "INFO"   | "Logging from Python module."                |                   |                                                           | "_udf_code.py"| "<module>"    | 6           |                |           |             |
| "ERROR"  | "なんか try の中で例外投げられたぽいっすよ."   | "error!"          | [                                                         | "_udf_code.py"| "main"        | 14          |                |           |             |
|          |                                              |                   |   "Traceback (most recent call last):",                   |               |               |             |                |           |             |
|          |                                              |                   |   "  File \"_udf_code.py\", line 12, in main",            |               |               |             |                |           |             |
|          |                                              |                   |   "  File \"_udf_code.py\", line 20, in throw_exception", |               |               |             |                |           |             |
|          |                                              |                   |   "Exception: error!",                                    |               |               |             |                |           |             |
|          |                                              |                   |   ""                                                      |               |               |             |                |           |             |
|          |                                              |                   | ]                                                         |               |               |             |                |           |             |
+----------+----------------------------------------------+-------------------+-----------------------------------------------------------+---------------+---------------+-------------+----------------+-----------+-------------+

EXCEPTION_STACKTRACE に、スタックトレースが出力されていますね。これで例外が吐かれても安心です。

Logging の外

ロギングを仕込んでいないところで例外が発生した場合は、当然ながら記録されません。

USE ROLE SYSADMIN;
CREATE OR REPLACE PROCEDURE raise_exception()
    RETURNS VARCHAR
    LANGUAGE PYTHON
    RUNTIME_VERSION='3.8'
    PACKAGES = ('snowflake-snowpark-python')
    HANDLER = 'run'
    as
$$
import logging


logger = logging.getLogger("raise_exception_logger")
logger.info("Logging from Python module.")

def run(session):
    msg = "No error"
    err_msg = "突然の死"

    logger.info(msg)  # ここまではくる
    
    raise ValueError(err_msg)
    logger.error(err_msg)  # ここにはこない
    return msg
$$;

USE ROLE ACCOUNTADMIN;
ALTER PROCEDURE raise_exception() SET LOG_LEVEL = INFO;

call raise_exception()

当然、クエリはエラーになります。

イベントテーブルを確認しましょう。

-- raise_exception_logger に絞って確認
SELECT
  RECORD['severity_text'] AS SEVERITY,
  VALUE AS MESSAGE
FROM
  IDENTIFIER($event_table_name)
WHERE
  SCOPE['name'] = 'raise_exception_logger'
  AND RECORD_TYPE = 'LOG';

result

+----------+-------------------------------+
| SEVERITY | MESSAGE                       |
+----------+-------------------------------+
| "INFO"   | "Logging from Python module." |
| "INFO"   | "No error"                    |
+----------+-------------------------------+

当然ながら、例外は記録されていません。エラー内容を確認するには SNOWFLAKE.ACCOUNT_USAGE.QUERY_HISTORY などの履歴テーブルを捜索しに行くことになります。

おわりに

Event Table を作成して、ストアドプロシージャ・UDFs にちょっとロギングを仕込むだけで、ログとイベントが取れるようになりました。
エラーメッセージは VALUE、エラーが発生した箇所やスタックトレースの情報は RECORD_ATTRIBUTES、など、必要なエラー情報はイベントテーブルに記録されているので安心です。（言語によってキーなどの持ち方は違うかも）
Snowflake の外で開発しているときはロギングを入れているけど、Snowflake の中ではログが見られないので、挙動が追えない。。。とお悩みの方も安心ですね。積極的にロギングを仕込んでいきましょう。^[4]

脚注

Snowflake 上でやるとしたら、ストアドの内部でログ出力用テーブルに吐く（自前イベントテーブル）、等すればできたかも。。。やったことはないです。 ↩︎
~アカウント単位の設定なので、アカウント全体でロガー名が重複しないか、など、名前に気を使ったほうがよさそう。~ リリースノート 9.4で、データベース単位の紐づけができるようになりました！データベース内での命名重複には気をつけましょう。 ↩︎
体感では、1分弱くらい待てば、ほぼ記録されている様子。メッセージ収集バッチが動くまでの待ち時間と思われる。 ↩︎
積極的に仕込みつつ、コストには気を付けたいところです ↩︎

Discussion