読者です 読者をやめる 読者になる 読者になる

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の値はどこかに保存されて使いまわされている?もしそうならかなり不便な気がするので何か思い違いをしている所があるのかもしれない。。