中野智文のブログ

データ・マエショリストのメモ

Airflow と格闘中(14)

nakano-tomofumi.hatenablog.com

のつづき。

エラーで scheduler が落ちる。

次のエラーで落ちる。

Traceback (most recent call last):
  File "/XXX/python/venv/bin/airflow", line 28, in <module>
    args.func(args)
  File "/XXX/python/venv/lib/python2.7/site-packages/airflow/bin/cli.py", line 831, in scheduler
    job.run()
  File "/XXX/python/venv/lib/python2.7/site-packages/airflow/jobs.py", line 200, in run
    self._execute()
  File "/XXX/python/venv/lib/python2.7/site-packages/airflow/jobs.py", line 1311, in _execute
    self._execute_helper(processor_manager)
  File "/XXX/python/venv/lib/python2.7/site-packages/airflow/jobs.py", line 1439, in _execute_helper
    (State.SCHEDULED,))
  File "/XXX/python/venv/lib/python2.7/site-packages/airflow/utils/db.py", line 53, in wrapper
    result = func(*args, **kwargs)
  File "/XXX/python/venv/lib/python2.7/site-packages/airflow/jobs.py", line 1027, in _execute_task_instances
    open_slots = pools[pool].open_slots(session=session)
KeyError: u'backfill'

普通に考えると、scheduler っていうのは絶対落ちてはNGなのだが、落ちる。

airflow の DAG は設定と実行を同じ pythonファイルで管理している。 scheduler は設定を知るために一旦 DAGファイル・フォルダのpython をすべて読み込む。 backfill では何を読むべきかを指定するのだが、scheduler は何を読むべきかは知らない。よってすべて読むわけである。 これはあくまで予想だが、その読み込んだ全てのファイルのうち、一つでも問題があると、scheduler ごと落ちる。

scheduler は各プロセスの死活監視などを行っているが、自身が死んだら何もならない。crond が死ぬようなものである。

ところで、上記のエラーは DAG ファイルのpool の設定が backfill と書いてあるところをコメントアウトしたら解決した。

webserver をデーモンで起動する

-D オプションをつければいいらしいが、ずっと stdin を待っている。すなわち、デーモンになってない。なぜ？ 分からない

とりあえず、コマンドの最後に & をつけよう！

ユニーク制約のエラー

トリガーで試みるも 次のようなエラーが吐かれていた。

[2017-05-31 16:07:15,817] {jobs.py:354} DagFileProcessor3855 ERROR - Got an exception! Propagating...
Traceback (most recent call last):
...
  File "/XXXX/python/venv/lib/python2.7/site-packages/airflow/models.py", line 4117, in verify_integrity
    session.commit()
...
IntegrityError: (pysqlite2.dbapi2.IntegrityError) UNIQUE constraint failed: task_instance.task_id, task_instance.dag_id, task_instance.execution_date [SQL: u'INSERT INTO task_instance (task_id, dag_id, execution_date, start_date, end_date, duration, state, try_number, hostname, unixname, job_id, pool, queue, priority_weight, operator, queued_dttm, pid) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)'] [parameters: ('task_name', 'dag_name', '2017-05-22 00:00:00.000000', None, None, None, None, 0, u'', 'user_name', None, None, 'bash_queue', 10, None, None, None)]

リトライ中になり、

[2017-05-31 16:12:31,562] {models.py:1126} DagFileProcessor4099 INFO - Dependencies all met for <TaskInstance: dag_name.task_name 2017-05-22 00:00:00 [up_for_retry]>
[2017-05-31 16:12:31,563] {jobs.py:1618} DagFileProcessor4099 INFO - Creating / updating <TaskInstance: dag_name.task_name 2017-05-22 00:00:00 [scheduled]> in ORM

となった後は、 fail した模様。

sqlite> .sch task_instance
CREATE TABLE "task_instance" (
        task_id VARCHAR(250) NOT NULL,
        dag_id VARCHAR(250) NOT NULL,
        execution_date DATETIME NOT NULL,
        start_date DATETIME,
        end_date DATETIME,
        duration FLOAT,
        state VARCHAR(20),
        try_number INTEGER,
        hostname VARCHAR(1000),
        unixname VARCHAR(1000),
        job_id INTEGER,
        pool VARCHAR(50),
        queue VARCHAR(50),
        priority_weight INTEGER,
        operator VARCHAR(1000),
        queued_dttm DATETIME, pid INTEGER,
        PRIMARY KEY (task_id, dag_id, execution_date)
);
CREATE INDEX ti_state_lkp ON task_instance (dag_id, task_id, execution_date, state);
CREATE INDEX ti_pool ON task_instance (pool, state, priority_weight);
CREATE INDEX ti_dag_state ON task_instance (dag_id, state);
CREATE INDEX ti_state ON task_instance (state);

から、UNIQUE制約は、primary key のみといったところか。中身を見てみると、

sqlite> select * from task_instance where task_id = 'task_name' and dag_id = 'dag_name';
task_name|dag_name|2017-05-22 00:00:00.000000|2017-05-31 16:12:34.099778|2017-05-3116:12:44.141016|10.041238|failed|2|host_name|user_name|161||bash_queue|10|BashOperator|2017-05-31 16:07:19.593213|25148

ということらしい。キューに入ったのは、先程のユニーク制約のエラーの後？？？　よくわからない。

[2017-05-31 16:07:18,138] {jobs.py:343} DagFileProcessor3857 INFO - Started process (PID=24635) to work on /dag_name.py
[2017-05-31 16:07:18,139] {jobs.py:516} DagFileProcessor3857 INFO - dag_id: None
[2017-05-31 16:07:18,141] {jobs.py:1523} DagFileProcessor3857 INFO - Processing file /dag_name.py for tasks to queue

とはなっている。

つづきは、

nakano-tomofumi.hatenablog.com

Airflow と格闘中(13)

nakano-tomofumi.hatenablog.com

のつづき

pause なんて知らない。

やっと原因の一つが分かった。

stackoverflow.com

DAGが （デフォルトで）pause されていたのだ。でも pause されているなんてどこにも書いていない。 Scheduling & Triggers の項目にも、Tutorial にも、 Quick Start にも。もちろんFAQ にも書かれていない。

このためにかなりの時間を使ったような気がする。

それでもまだ動かない

まだまだなのだよ。

つづく。

nakano-tomofumi.hatenablog.com

Airflow と格闘中(12)

nakano-tomofumi.hatenablog.com

Scheduling & Triggers の To Keep in Mind を読む。

以下を読む。

Scheduling & Triggers — Airflow Documentation

以下超訳（カッコ内は自分の感想）

  • DAG Run は start_date から始まるよ。これは日付をしないときの話かな。（trigger とは関係なさそう。）
  • schedule_interval に基づき、連続した DAG Runs は作成されるよ。（そりゃそうだろうね。）
  • 再実行をするために状態の初期化をするときに覚えていたほうがいい重要なことは、DAG Runの状態も、その実行を triggerするタスクを見に行くかどうかを決定する。 （今はなんの依存もないタスクであってもtrigger_dags で実行されないからとりあえずいいか。）

ここでタスクをアンブロックすることができる方法がある。（おや、ブロックされているの？）

  • UIから…（すみません、まだUIとかのレベルではないのでスキップしします）
  • airflow clear -h はたくさんのオプションがあって次のものを指定できる。 日付の範囲、task_id の正規表現、upstream, downstream の関連（！）、ターゲットタスクのインスタンスの失敗や成功。 （インスタンスというのは実行かな？　失敗しても、idempotent 的には、永遠に失敗だから、状態をクリアしないと再実行されないのかな…って、そんな感じのメッセージは現在のところ見てないのでこのあたりは関係なさそう。ところで　upstream やdownstream の状態を削除できるのは、luigi ではできなかったことなので、でかい気がするなー。）
  • UIを通してタスクを成功とマークすることができる。これは主に誤った失敗（すなわち成功している話）の修正や例えばairflow外から修正するためのものである。
  • CLIのサブコマンド airflow backfill には --mark_success というフラグがあり、日付を指定するのと同様に DAG のsubsection をしているすることを許可する。（ちなみに、--mark_success オプションは上の意味と同じで、実行せずに成功とマークする機能）

で結論。trigger_dag が上手くいかない手がかりは得られなかった。

UI を見る

UI は本当に見れているのか。

airflow webserver -p 8080

みたいな感じで起動。scheduler などとは直接通信をせず、sqlite の中身をみて現状を確認する様子。よって、scheduler が動いていなくてもWebの画面は正常に表示されるし、 trigger_dag のサブコマンドを実行すると、しっかり web 上のステータスもrunningに追加・変更されるので、まるで scheduler が動いているかののような錯覚を覚えるが、 scheduler は webサーバを起動しても特に動くわけではないし、running のステータスも、実は嘘で、running の状態になるように設定されましたくらいの意味。

重要な設定

Google グループ

くそっ、早く気がつくべきだった。

airflow.cfg に下記を設定

[core]
load_examples = False

デバッグコードを埋め込む

以前からあるエラーメッセージ

nakano-tomofumi.hatenablog.com

の原因が何であるかわからない。 すなわち、dag_stats.dag_id と dag_run.dag_id は空である、とのことであるが、これは一体どうなっているのか。

調べていくと、jobs.py の関数 process_file が怪しいことがわかった。

そして、実行されるべきDAG の入ったリスト dags は空であることが判明した。 また、何故空なのか、調べると、ターゲットのDAGが、is_paused となっていることが分かった。

つづく。

nakano-tomofumi.hatenablog.com

自宅macのJuliaLang環境を治す(3)

nakano-tomofumi.hatenablog.com

の続き

ちょっと変化があった。

$ brew test -v julia
Testing staticfloat/julia/julia
==> Using the sandbox
/usr/bin/sandbox-exec -f /tmp/homebrew20170526-45995-169fe4y.sb /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/bin/ruby -W0 -I /usr/local/Homebrew/Library/Homebrew -- /usr/local/Homebrew/Library/Homebrew/test.rb /usr/local/Homebrew/Library/Taps/staticfloat/homebrew-julia/julia.rb -v
==> /usr/local/Cellar/julia/0.5.1/bin/julia -e Base.runtests("core")
WARNING: Error during initialization of module CHOLMOD:
ErrorException("could not load library "libcholmod"
dlopen(libcholmod.dylib, 1): Library not loaded: /usr/local/opt/openblas-julia/lib/libopenblasp-r0.2.19.dylib
  Referenced from: /usr/local/Cellar/julia/0.5.1/lib/julia/libcholmod.dylib
  Reason: image not found")
WARNING: Error during initialization of module CHOLMOD:
ErrorException("could not load library "libcholmod"
dlopen(libcholmod.dylib, 1): Library not loaded: /usr/local/opt/openblas-julia/lib/libopenblasp-r0.2.19.dylib
  Referenced from: /usr/local/Cellar/julia/0.5.1/lib/julia/libcholmod.dylib
  Reason: image not found")
     * core                 WARNING: Method definition f(Tuple{Vararg{Int64, #N<:Any}}, AbstractArray{#T<:Any, #N<:Any}) in module Main at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:723 overwritten at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:729.
WARNING: Method definition f() in module JLCall14301 at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:3546 overwritten at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:3556.
WARNING: static parameter T does not occur in signature for bad_tvars at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:4621.
The method will not be callable.
 in  28.85 seconds, maxrss 1427.54 MB
    SUCCESS

--build-from-source が大事

そもそも、せっかく source からコンパイルしたopenblastのライブラリを使ってないのじゃないの？ という疑惑がわく。julia 本体も、--build-from-source をつけてインストール。

$ brew reinstall --build-from-source julia
...
🍺  /usr/local/Cellar/julia/0.5.1: 753 files, 140.5MB, built in 8 minutes 8 seconds
$ brew test -v julia
Testing staticfloat/julia/julia
==> Using the sandbox
/usr/bin/sandbox-exec -f /tmp/homebrew20170526-98332-164n2k7.sb /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/bin/ruby -W0 -I /usr/local/Homebrew/Library/Homebrew -- /usr/local/Homebrew/Library/Homebrew/test.rb /usr/local/Homebrew/Library/Taps/staticfloat/homebrew-julia/julia.rb -v
==> /usr/local/Cellar/julia/0.5.1/bin/julia -e Base.runtests("core")
     * core                 WARNING: Method definition f(Tuple{Vararg{Int64, #N<:Any}}, AbstractArray{#T<:Any, #N<:Any}) in module Main at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:723 overwritten at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:729.
WARNING: Method definition f() in module JLCall14301 at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:3546 overwritten at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:3556.
WARNING: static parameter T does not occur in signature for bad_tvars at /usr/local/Cellar/julia/0.5.1/share/julia/test/core.jl:4621.
The method will not be callable.
 in  28.77 seconds, maxrss 1426.77 MB
    SUCCESS

ちょっと時間がかかったけど、インストールは多少の警告は出るもののうまくいったぽい。

めでたしめでたし。

補足

これまでの苦労が全くのムダのようなことが…

nakano-tomofumi.hatenablog.com

自宅macのJuliaLang環境を治す(2)

nakano-tomofumi.hatenablog.com のつづき。

xcode を入れる。

app store にて。

julia を再インストール

$ brew reinstall julia
Error: You have not agreed to the Xcode license. Please resolve this by running:
  sudo xcodebuild -license accept

とでた。そこで上記のコマンドを実行し、再び julia をインストールするのも失敗。

web の話

Can't load module libopenblas · Issue #76 · staticfloat/homebrew-julia · GitHub

やっぱりこういうのしっかり読むべきだよね。

最後の方に、次を実行しろと書いてある。

brew rm --force gcc gfortran openblas-julia arpack-julia suite-sparse-julia && brew update && brew install julia

R と Julia を既にインストールしてしまっているので、エラーが出たが(--force とは何だったか)、先にそれらを消してから、 再度実行すると、無事インストールされる。

ところが、また同じエラー。

$ brew install --HEAD julia
...
==> make prefix=/usr/local/Cellar/julia/HEAD-bac32d3 USE_BLAS64=0 TAGGED_RELEASE_BANNER="homebrew-julia release" FC=/usr/local/bin/gfortran LLVM_CONFIG=llvm-config-3.7 LLVM_VER=3.7.1 LOCALBASE=/usr/local/Cellar/julia/HEAD-bac32d3 USECLANG=1
Last 15 lines from /Users/nakanotomofumi/Library/Logs/Homebrew/julia/02.make:
            new_enter->setMetadata(LLVMContext::MD_dbg, dbg);
                                   ^~~~~~~~~~~~~
/usr/local/Cellar/llvm37-julia/3.7.1_3/lib/llvm-3.7/include/llvm/IR/DebugLoc.h:23:9: note: forward declaration of 'llvm::LLVMContext'
  class LLVMContext;
        ^
/private/tmp/julia-20170525-4774-rwb8x2/src/llvm-lower-handlers.cpp:218:29: error: incomplete type 'llvm::LLVMContext' named in nested name specifier
            sj->setMetadata(LLVMContext::MD_dbg, dbg);
                            ^~~~~~~~~~~~~
/usr/local/Cellar/llvm37-julia/3.7.1_3/lib/llvm-3.7/include/llvm/IR/DebugLoc.h:23:9: note: forward declaration of 'llvm::LLVMContext'
  class LLVMContext;
        ^
3 errors generated.
make[1]: *** [llvm-lower-handlers.o] Error 1
make[1]: *** Waiting for unfinished jobs....
make: *** [julia-src-release] Error 2

If reporting this issue please do so at (not Homebrew/brew or Homebrew/core):
https://github.com/staticfloat/homebrew-julia/issues

These open issues may also help:
julia quasi-broken after gcc update https://github.com/staticfloat/homebrew-julia/issues/238

うーむ、これもうまくいかない。

よって次のコマンドを実行。

$ brew reinstall --build-from-source openblas-julia

gfortran のコンパイル(gfortran 自身のコンパイルではありませんでした。)でしばらく時間がかかる。おそらく数時間はかかるんじゃないかな。今日はここでおしまい。と思ったらでた。

$ brew reinstall --build-from-source openblas-julia
==> Reinstalling staticfloat/julia/openblas-julia
==> Using Homebrew-provided fortran compiler.
This may be changed by setting the FC environment variable.
==> Downloading http://github.com/xianyi/OpenBLAS/archive/v0.2.19.tar.gz
==> Downloading from https://codeload.github.com/xianyi/OpenBLAS/tar.gz/v0.2.19
######################################################################## 100.0%
==> make FC=/usr/local/bin/gfortran
==> make PREFIX=/usr/local/Cellar/openblas-julia/0.2.19 install
==> Caveats
This formula is keg-only, which means it was not symlinked into /usr/local,
because Conflicts with openblas in homebrew-science..

If you need to have this software first in your PATH run:
  echo 'export PATH="/usr/local/opt/openblas-julia/bin:$PATH"' >> ~/.bash_profile

For compilers to find this software you may need to set:
    LDFLAGS:  -L/usr/local/opt/openblas-julia/lib
    CPPFLAGS: -I/usr/local/opt/openblas-julia/include

/usr/local/opt/openblas-julia/bin や、/usr/local/Cellar/openblas-julia/0.2.19/bin には何もないことを確認 ^^;

つづきは、 nakano-tomofumi.hatenablog.com

自宅のMacにRを入れる

背景

Juliaを入れ直そうと思ったら、うまくいかない。

Rを入れる。

とりあえず、Rをいれればなんとかなるかもしれない。

OS XにRをインストールするときに知っておきたいこと - Qiita

にしたがって、brew で入れる方法を試すことに

$ brew tap homebrew/science
$ brew install R

==> Installing homebrew/science/r dependency: readline
==> Caveats
This formula is keg-only, which means it was not symlinked into /usr/local,
because macOS provides the BSD libedit library, which shadows libreadline.
In order to prevent conflicts when programs look for libreadline we are
defaulting this GNU Readline installation to keg-only..

For compilers to find this software you may need to set:
    LDFLAGS:  -L/usr/local/opt/readline/lib
    CPPFLAGS: -I/usr/local/opt/readline/include

==> Installing homebrew/science/r dependency: gettext
==> Caveats
This formula is keg-only, which means it was not symlinked into /usr/local,
because macOS provides the BSD gettext library & some software gets confused if both are in the library path.

If you need to have this software first in your PATH run:
  echo 'export PATH="/usr/local/opt/gettext/bin:$PATH"' >> ~/.bash_profile

For compilers to find this software you may need to set:
    LDFLAGS:  -L/usr/local/opt/gettext/lib
    CPPFLAGS: -I/usr/local/opt/gettext/include

==> Installing homebrew/science/r
==> Caveats
To enable rJava support, run the following command:
  R CMD javareconf JAVA_CPPFLAGS=-I/System/Library/Frameworks/JavaVM.framework/Headers
If you've installed a version of Java other than the default, you might need to instead use:
  R CMD javareconf JAVA_CPPFLAGS="-I/System/Library/Frameworks/JavaVM.framework/Headers -I/Library/Java/JavaVirtualMachines/jdk<version>.jdk/"
(where <version> can be found by running `java -version`, `/usr/libexec/java_home`, or `locate jni.h`), or:
  R CMD javareconf JAVA_CPPFLAGS="-I/System/Library/Frameworks/JavaVM.framework/Headers -I$(/usr/libexec/java_home | grep -o '.*jdk')"

気になるメッセージは記録しておこう。

動作確認

> binom.test(1,2)

    Exact binomial test

data:  1 and 2
number of successes = 1, number of trials = 2, p-value = 1
alternative hypothesis: true probability of success is not equal to 0.5
95 percent confidence interval:
 0.01257912 0.98742088
sample estimates:
probability of success
                   0.5

問題なし、と思う。

virtualbox の時刻がずれている

背景

make をやっても、うまくいかないことがある。 ターゲットを共通化するために、前処理の複数のターゲットのアウトプットを同じものにしてあったが、 時刻がずれているため？、本来意図してない処理が呼ばれてしまう模様。

ntpd がインストールされているかどうかを確認する。

$ ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 ntp00.iij.net   210.130.188.1    3 u  332 1024  377    2.571  1065461 2351.27
 ntp01.iij.net   210.130.188.1    3 u  621 1024  377    2.735  1066141 1942.83
 ntp02.iij.net   210.130.188.1    3 u  761 1024  377    2.874  1065675 2352.60

で確認。大幅にずれていることを確認した。

時刻を設定する

大幅にずれている場合は自動調整されない。 ntpdate ntp.nict.jp などのコマンドで設定するが、先に ntpd を止めておかないと、

24 May 13:16:45 ntpdate[8055]: the NTP socket is in use, exiting

みたいなエラーが出てしまう。

$ sudo service ntp stop
 * Stopping NTP server ntpd
   ...done.
$ sudo ntpdate ntp.nict.jp
24 May 13:44:18 ntpdate[8105]: step time server 133.243.238.243 offset 1071.115719 sec
$ sudo service ntp start
 * Starting NTP server ntpd
   ...done.
$ ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 ntp00.iij.net   210.130.188.1    3 u   11   64    1    2.312    0.382   0.000
 ntp01.iij.net   210.130.188.1    3 u   10   64    1    3.126    0.034   0.000
 ntp02.iij.net   210.130.188.1    3 u    9   64    1    3.070   -0.137   0.000

防止策

また発生するでしょう。

makefile のターゲットの先頭に、次のように書いた。

test  `ntpq -p | grep '*' | wc -l` -ge 1 # clock sync check

意味：ntpq -p で * の行が一行以上あれば(syncされたサーバがある)OK。なければ失敗。