DiedUnknownId - distributed-processのデバッグ
parallel and concurrent haskellの14章を読んでいてtyped channelを用いた実装をやってみた際、なかなかデバッグできず苦労したのでメモ。
まず私の環境では以下のようにmoduleを分けて実装していた。
Channel.hs
module Channel where
data Message = Ping (SendPort ProcessId) deriving (Typeable, Generic)
instance Binary Message
pingServerChannel :: Process ()
pingServerChannel = do
Ping chan <- expect
say $ printf "ping received from %s" (show chan)
mypid <- getSelfPid
sendChan chan mypid
$(remotable ['pingServerChannel])
master :: [NodeId] -> Process ()
master peers = do
ps <- forM peers $ \nid -> do
say $ printf "spawning on %s" (show nid)
spawn nid $(mkStaticClosure 'pingServerChannel)
ports <- forM ps $ \pid -> do
say $ printf "pinging %s" (show pid)
(sp, rp) <- newChan
withMonitor pid $ do
send pid $ Ping sp
receiveWait
[ match $ \(ProcessMonitorNotification _ deadpid reason) -> do
say $ printf "process %s died: %s" (show deadpid) (show reason)
terminate
]
return rp
forM_ ports $ \port -> do
_ <- receiveChan port
return ()
say "All pongs received"
terminate Main.hs
import Channel
main :: IO ()
main = do
(command:args) <- getArgs
case command of
"simple" -> withArgs args $ distribMain (\_ -> master) Main.__remoteTable
"channel" -> withArgs args $ distribMain Channel.master Main.__remoteTable
...14章の例をそれぞれ実装するためのcabalファイルで一つのExecutableとしてdistributedというバイナリを作成するようにしていた。そのためMain.hsでは第一引数でどの例を実行するのか指定できるようにし、それぞれの実装は別のモジュールとして分けていた。
わかりづらいと思うのでコードの全体についてはこちらを。
https://github.com/y-kamiya/parallel-concurrent-haskell/tree/master/src/Distributed
slaveノードを一つ作り、上記のコードを実行すると以下のような結果になる。
$ ./dist/build/distributed/distributed channel slave 44445 & $ ./dist/build/distributed/distributed channel Sun Mar 22 03:13:44 UTC 2015 pid://localhost:44444:0:10: pinging pid://localhost:44445:0:18 Sun Mar 22 03:13:44 UTC 2015 pid://localhost:44444:0:10: process pid://localhost:44445:0:18 died: DiedUnknownId distributed: ProcessTerminationException
withMonitorによる監視の時点でProcessMonitorNotificationとしてDiedUnknownIdが返って来ていると考えられる。
ただ、これだけだと悪い部分の原因を突き止めることができない。hackageやソースを見るとDiedUnknownIdはこれを表しているらしい。
DiedUnknownId Invalid (process/node/channel) identifier
わからん。
のでググっていろいろ調べてみるとこんなJIRAのチケットが上がっていた。
https://cloud-haskell.atlassian.net/browse/DP-96
こんな感じで環境変数を定義して実行するとdebug traceが取れるらしいのでやってみた。
$ DISTRIBUTED_PROCESS_TRACE_FLAGS=d DISTRIBUTED_PROCESS_TRACE_CONSOLE=yes ./dist/build/distributed/distributed channel
実行結果。
$ DISTRIBUTED_PROCESS_TRACE_FLAGS=d DISTRIBUTED_PROCESS_TRACE_CONSOLE=yes ./dist/build/distributed/distributed channel Sun Mar 22 03:46:18 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:7 DiedNormal Sun Mar 22 03:46:18 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:9 DiedNormal Sun Mar 22 03:46:19 UTC 2015 pid://localhost:44444:0:10: pinging pid://localhost:45000:0:13 Sun Mar 22 03:46:19 UTC 2015 pid://localhost:44444:0:10: process pid://localhost:45000:0:13 died: DiedUnknownId distributed: ProcessTerminationException
[trace]という行が追加された。ただ、masterプロセス側のものだけのよう。DiedNormalなので何かの処理が正常終了したらしい。
JIRAのチケットをもう少し読んでみるとリモートのプロセスのデバッグメッセージを取得するにはそれ用のコードを追加する必要があるとわかった。
Note that todo this for a remote node (i.e., writing out trace output for a node residing on another host or os process), you'd need to use the enableTraceRemote primitive and it's associated Apis.
enableTraceRemoteという関数を使うらしい。ということでそれがあるモジュールを調べてみる。
Control/Distributed/Process/Management/Internal/Trace/Remote.hs
-- | Remote Table.
remoteTable :: RemoteTable -> RemoteTable
remoteTable = registerStatic "$enableTraceRemote" (toDynamic enableTraceRemote)
enableTraceRemote :: ProcessId -> Process ()
enableTraceRemote pid =
getSelfPid >>= enableTrace >> relay pid
-- | Starts a /trace relay/ process on the remote node, which forwards all trace
-- events to the registered tracer on /this/ (the calling process') node.
startTraceRelay :: NodeId -> Process ProcessId
startTraceRelay nodeId = do
withRegisteredTracer $ \pid ->
spawn nodeId $ cpEnableTraceRemote pid
-- | Set the given flags for a remote node (asynchronous).
setTraceFlagsRemote :: TraceFlags -> NodeId -> Process ()
setTraceFlagsRemote flags node = do
nsendRemote node
"trace.controller"
((Nothing :: Maybe (SendPort TraceOk)), flags)
||<
丁寧にコメントが付けられているおかげでなんとなくわかった。setTraceFlagsRemoteで特定のノードのどんな種類のデバッグメッセージを追うか指定し、startTraceRelayでそれをmaster側にメッセージとして送るためのプロセスを起動するという感じ。enableTraceRemoteでtrace用の関数がリモート側で使えるようになるということだろうか。
これをもとに実装してみたのがこちら。（変更したところのみ）
Channel.hs
>||
import qualified Control.Distributed.Process.Management.Internal.Trace.Remote as TR
import qualified Control.Distributed.Process.Management.Internal.Trace.Types as TT
master :: [NodeId] -> Process ()
master peers = do
let flags = TT.defaultTraceFlags { TT.traceDied = Just TT.TraceAll }
ps <- forM peers $ \nid -> do
say $ printf "spawning on %s" (show nid)
TR.setTraceFlagsRemote flags nid
_ <- TR.startTraceRelay nid
spawn nid $(mkStaticClosure 'pingServerChannel) Main.hs
import qualified Control.Distributed.Process.Management.Internal.Trace.Remote as TR
main :: IO ()
main = do
(command:args) <- getArgs
case command of
"simple" -> withArgs args $ distribMain (\_ -> master) Main.__remoteTable
"channel" -> withArgs args $ distribMain Channel.master TR.remoteTable
...これを実行した結果がこちら。
$ DISTRIBUTED_PROCESS_TRACE_FLAGS=d DISTRIBUTED_PROCESS_TRACE_CONSOLE=yes ./dist/build/distributed/distributed channel Sun Mar 22 04:06:20 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:7 DiedNormal Sun Mar 22 04:06:20 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:9 DiedNormal Sun Mar 22 04:06:21 UTC 2015 pid://localhost:44444:0:10: spawning on nid://localhost:45000:0 Sun Mar 22 04:06:21 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:4 DiedDisconnect Sun Mar 22 04:06:21 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:4 DiedDisconnect Sun Mar 22 04:06:21 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:4 DiedDisconnect Sun Mar 22 04:06:21 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:4 DiedDisconnect Sun Mar 22 04:06:21 UTC 2015 [trace] MxProcessDied pid://localhost:44444:0:4 DiedDisconnect Sun Mar 22 04:06:21 UTC 2015 pid://localhost:44444:0:10: pinging pid://localhost:45000:0:15 Sun Mar 22 04:06:21 UTC 2015 [trace] MxProcessDied pid://localhost:45000:0:15 (DiedException "user error (Error: Could not resolve closure: Invalid static label 'Channel.pingServerChannel')") Sun Mar 22 04:06:21 UTC 2015 [trace] [network] invalid request: 12884902916 Sun Mar 22 04:06:21 UTC 2015 [trace] [network] invalid request: 12884902916 Sun Mar 22 04:06:21 UTC 2015 [trace] [network] invalid request: 12884902916 Sun Mar 22 04:06:21 UTC 2015 pid://localhost:44444:0:10: process pid://localhost:45000:0:15 died: DiedUnknownId distributed: ProcessTerminationException
DiedExceptionの内容が取得できた。Channel.pingServerChannelというのがremoteTableに登録されてないということのよう。登録する部分を$(remoteTable ['Channel.pingServerChannel])という形にしてみたがそれでもうまくいかなかった。RemoteTableの仕組みについて調べてみる必要がありそうだが、それはまた別の機会に。
今回はモジュール分けせずに一つのファイル内に実装することで上記の問題は解決した。
デバッグメッセージとして追えるものにはいくつか種類があるようで、今回使ったのはtraceDie。以下のモジュールに定義されているのでプロセスが死んだとき以外でデバッグメッセージを取得した場合はそのフラグを指定することで取ることができる。
Control.Distributed.Process.Management.Internal.Trace.Types
また、これをやっている最中におかしいなと感じた点が、コード修正してビルドしなおしてもRemoteTableが更新されていないかのような挙動をした場合があったこと。一度登録したRemoteTableの値はどこかに保存されて使いまわされている？もしそうならかなり不便な気がするので何か思い違いをしている所があるのかもしれない。。
