Python
JavaScript
redash

Redash 開発時のデバッグ方法あれこれ

はじめに

Redash の開発におけるデバッグ方法を「サーバサイド」「ワーカ」「フロントエンド」に分類して紹介します。

開発環境の構築については次のエントリを参考にしてください。

サーバサイド

Redash のサーバサイドは Python による軽量フレームワーク Flask で書かれています。

注意

Redash では Python 2.7 を使っているのですが、一部で __future__ モジュールを使っているファイルがあります。このモジュールを使うと記述が一部 Python 3 になるのですが、Python 3 では後方互換性が失われていています。シンタックスエラーになった場合は該当のファイルで __future__ モジュールが使われていないか確認してください。

該当するファイル一覧は例えば Github の検索結果から確認できます。

print デバッグ

確認したい値を標準出力に出力する、単純かつ古典的な手法です。

次はモデル定義がまとまっている models.py で、ユーザ情報を辞書形式で返す User#to_dict にユーザの名前を出力する処理を追加した例です。デバッグ用文字列である事を分かりやすくするため、文字列 debug: ======= を一緒に出力しています。

redash/models.py
def to_dict(self, with_api_key=False):
    print "debug: ======="  # 追加
    print self.name         # 追加
    d = {
        'id': self.id,
        'name': self.name,
        'email': self.email,

上記の仕込みを行った後、トップページの右上にあるユーザアイコンをクリックして「Edit Profile」をクリックします。

edit_profile.png

サーバを実行しているターミナルに次の様にユーザの名前が出力されます。

[2017-12-28 08:59:38,752][PID:34710][DEBUG][metrics] table=organizations query=select duration=2.63
[2017-12-28 08:59:38,752][PID:34710][DEBUG][root] Current organization: home (15) (slug: default)
[2017-12-28 08:59:38,756][PID:34710][DEBUG][metrics] table=users query=select duration=2.63
[2017-12-28 08:59:38,761][PID:34710][DEBUG][metrics] table=users query=select duration=2.74
debug: =======
kyoshida
[2017-12-28 08:59:38,763][PID:34710][INFO][metrics] method=GET path=/api/users/10 endpoint=user status=200 content_type=application/json content_length=366 duration=15.14 query_count=3 query_duration=7.99
[2017-12-28 08:59:38,765][PID:34710][INFO][werkzeug] 127.0.0.1 - - [28/Dec/2017 08:59:38] "GET /api/users/10 HTTP/1.1" 200 -

サーバを実行しているターミナルは Redashの開発環境を作る手順 - Qiita だと、次のコマンドを実行したターミナルになります。

bin/run ./manage.py runserver --debugger --reload --host 0.0.0.0

print デバッグとして、次のように logging モジュールを使う方法もあります。

models.py
  def to_dict(self, with_api_key=False):
      logging.debug('=======')  # 追加
      logging.debug(self.name)  # 追加
      d = {
          'id': self.id,
          'name': self.name,
          'email': self.email,

該当処理が実行されると次のような出力が行われます。

[2017-12-28 10:43:16,225][PID:3375][DEBUG][metrics] table=users query=select duration=2.92
[2017-12-28 10:43:16,232][PID:3375][DEBUG][metrics] table=users query=select duration=3.47
[2017-12-28 10:43:16,233][PID:3375][DEBUG][root] =======
[2017-12-28 10:43:16,233][PID:3375][DEBUG][root] kyoshida
[2017-12-28 10:43:16,234][PID:3375][INFO][metrics] method=GET path=/api/users/10 endpoint=user status=200 content_type=application/json content_length=366 duration=20.34 query_count=3 query_duration=9.42
[2017-12-28 10:43:16,236][PID:3375][INFO][werkzeug] 127.0.0.1 - - [28/Dec/2017 10:43:16] "GET /api/users/10 HTTP/1.1" 200 -

ちなみに logging モジュールは事前に

import logging

を宣言しておく必要があります(models.py には宣言済み)。

pdb

print デバッグは確認対象が特定できている場合には便利なのですが、対象があいまいだとアタリをつけて出力を確認し、再度対象を指定し直して実行、の流れを繰り返す事になります。

例えば先程の print デバッグでユーザの所属グループも確認したくなった場合、その定義を行い、再度ページを読み込む必要があります。

models.py
def to_dict(self, with_api_key=False):
    print "debug: ======="
    print self.name
    print self.group_ids         # さらに追加
    d = {
        'id': self.id,
        'name': self.name,
        'email': self.email,

さらにユーザの id も確認したくなったらまた修正して読み込むのは面倒です。

また、出力が大量にあると debug: ======= のような目印を入れていても見逃してしまいやすくなるため、grep のようなフィルタリングを導入する必要が出てきてしまいます。

このようなケースで pdb を使うと効率的にデバッグを行えるようになります。

pdb の起動方法は、まず確認したい箇所に import pdb; pdb.set_trace() を定義します。その後、処理が該当の箇所を通るとデバッガが起動します。

先程の models.py の例では、次のように定義を追加します。

models.py
def to_dict(self, with_api_key=False):
    import pdb; pdb.set_trace()  # 追加
    d = {
        'id': self.id,
        'name': self.name,
        'email': self.email,

対象ページを読み込むと、サーバを起動したターミナルでデバッガが起動します。

[2017-12-28 09:49:06,485][PID:67389][DEBUG][metrics] table=organizations query=select duration=6.34
[2017-12-28 09:49:06,486][PID:67389][DEBUG][root] Current organization: home (15) (slug: default)
[2017-12-28 09:49:06,493][PID:67389][DEBUG][metrics] table=users query=select duration=3.50
[2017-12-28 09:49:06,501][PID:67389][DEBUG][metrics] table=users query=select duration=4.37
> /Users/katsuhiko.yoshida/work/redash/redash/models.py(416)to_dict()
-> d = {
(Pdb) 

ちょっと見づらいので、続きはシンタックスハイライトを効かせて表示します。

(Pdb) print self.name
kyoshida
(Pdb) self.name         # print なしでも値が確認できる
u'kyoshida'
(Pdb) self.group_ids    # コンテキストに合わせて値が確認できる 
[22, 23]
(Pdb) l                 # 周辺のソースコードを表示
411                 kwargs['email'] = kwargs['email'].lower()
412             super(User, self).__init__(*args, **kwargs)
413
414         def to_dict(self, with_api_key=False):
415             import pdb; pdb.set_trace()
416  ->         d = {
417                 'id': self.id,
418                 'name': self.name,
419                 'email': self.email,
420                 'profile_image_url': self.profile_image_url,
421                 'groups': self.group_ids,
(Pdb) n                 # 次の行に進む
> /Users/katsuhiko.yoshida/work/redash/redash/models.py(417)to_dict()
-> 'id': self.id,
(Pdb) c                 # 処理を再開

pdb の詳細についてはドキュメントを参照してください。

ちなみに import pdb; pdb.set_trace()import pdbpdb.set_trace() の2つの処理を1行で実行しています。仕組みとして、2回目以降の import は読まれないので、次のように2回目以降だからと言って import db を除く必要はありません。

models.py
def to_dict(self, with_api_key=False):
    import pdb; pdb.set_trace()  # 1個目
    d = {
        'id': self.id,
        'name': self.name,
        'email': self.email, ...}
    pdb.set_trace()  # import db 無し

ワーカ

Redash ではワーカ(タスクキュー)として Celery を使っています。
ワーカのデバッグにはサーバサイドと同様に print デバッグが使えますが、pdb には先に述べた通常の方法ではなく、Celery 用の指定が必要です。

次は Python データソースのクエリを実行する時のメソッド run_query にデバッグ用定義を入れた例です。

redash/query_runner/python.py
 def run_query(self, query, user):
     from celery.contrib import rdb; rdb.set_trace() # 追加
     try:
         error = None

         code = compile_restricted(query, '<string>', 'exec')

サーバはコードを修正すると自動的にリロードされるのですが、ワーカは自動的にリロードされません。手動でプロセスを終了(終了シグナルの送信 Ctrl + C)して、再起動します。

[2017-12-28 12:41:15,648][PID:52756][WARNING][MainProcess] celery@JMPC-077.local ready.
[2017-12-28 12:41:20,101][PID:52828][WARNING][Worker-6] Remote Debugger:6905: Please telnet into 127.0.0.1 6905.

Type `exit` in session to continue.

Remote Debugger:6905: Waiting for client...

上記のようにデバッグ用のポート番号が出力されるので別のターミナルから telnet で接続します。

telnet localhost 6905
Trying ::1...
telnet: connect to address ::1: Connection refused
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
> /Users/katsuhiko.yoshida/work/redash/redash/query_runner/python.py(221)run_query()
-> try:
(Pdb)

接続成功後の pdb の操作は通常と同じです。

(Pdb) query
u'print "Hello world!"'

フロントエンド

フロントエンドでは JavaScript フレームワークとして Angular が使用されています。ここでは Google Chrome の Dev Tools で確認する方法を紹介します。

print デバッグ

例として、クエリ実行(「Execute」ボタンを押した)時に通る executeQuery 内でログを出力してみます。

client/app/pages/queries/view.js
  $scope.executeQuery = () => {
    console.info($scope.query);   // 追加
    if (!$scope.canExecuteQuery()) {
      return;
    }

クエリを実行するとコンソールに $scope.query の値が出力されます。

log_info.png

console だとログ出力の一括オン・オフが切り替えられないので、$logProvider を使う方法もあります。詳しくは次を参考にしてください。

Chrome Dev Tools でブレークポイント設置

Chrome Dev Tools はより手軽で複雑なデバッグが行なえます。

まずは Sources タブで表示される開発環境のソースコードが下記のディレクトリにあるので確認します。

webpack_dir.png

ブレークポイントとして、pages/queries/view.js$scope.executeQuery 内にブレークポイントを置きます。

画面からクエリ実行を行うと該当のブレークポイントで処理が止まるので、その状況での変数や呼び出し元などが確認できます。
chrome_break.png

ブレークポイントを置いてのに処理が止まらない場合

開発用のURL(ポート番号)にアクセスしているかを確認します。デフォルトでは本番用は localhost:5000、開発用は localhost:8080 になります。

開発用の URL にアクセス出来ない場合は開発用ポートが空いているかを確認します。

次は開発用ポート番号が8080で空いている場合の出力例です。

netstat -an | grep 8080
tcp4       0      0  127.0.0.1.8080         *.*                    LISTEN

空いていない(上記のような出力が行われない場合)は起動します。

npm run start