Added lager for logging

5 files changed, 24 insertions, 2 deletions

diff --git a/src/db.erl b/src/db.erl
index 413f4b9..fade7ce 100644
--- a/src/db.erl
+++ b/src/db.erl
@@ -160,7 +160,9 @@ handle_call({add, {LeafHash, EntryHash, Data, Index}}, _From, State) ->
     {reply, ok, State};
 
 handle_call({add, {LeafHash, Data}}, _From, State) ->
+    lager:debug("add leafhash ~p", [LeafHash]),
     ok = perm:ensurefile(entry_root_path(), LeafHash, Data),
+    lager:debug("leafhash ~p added", [LeafHash]),
     {reply, ok, State};
 
 handle_call({add_entryhash, {LeafHash, EntryHash}}, _From, State) ->
diff --git a/src/fsyncport.erl b/src/fsyncport.erl
index 7e2bf11..5084fdd 100644
--- a/src/fsyncport.erl
+++ b/src/fsyncport.erl
@@ -22,11 +22,13 @@ call_port(Msg) ->
     end.
 
 init(ExtPrg) ->
+    lager:debug("starting fsync service"),
     register(fsyncport, self()),
     process_flag(trap_exit, true),
     Ports = lists:map(fun(_N) -> open_port({spawn_executable, ExtPrg},
                                            [{packet, 2}]) end,
 		      lists:seq(1, 32)),
+    lager:debug("fsync service started", []),
     loop(Ports).
 
 loop(Ports) ->
@@ -34,12 +36,14 @@ loop(Ports) ->
 loop(IdlePorts, BusyPorts, Waiting) ->
     receive
 	{call, Caller, {fsync, Path}} ->
+            lager:debug("fsync incoming request: ~p", [Path]),
 	    case IdlePorts of
 	        [] ->
 		    loop(IdlePorts,
                          BusyPorts,
                          queue:in({Caller, Path}, Waiting));
 	        [Port | Rest] ->
+                    lager:debug("fsync port ~p assigned to request ~p", [Port, Path]),
 		    Port ! {self(), {command, Path}},
 		    loop(Rest,
                          dict:store(Port, {Caller, os:timestamp()}, BusyPorts),
@@ -47,6 +51,7 @@ loop(IdlePorts, BusyPorts, Waiting) ->
             end;
 
 	{Port, {data, Data}} when is_port(Port) ->
+            lager:debug("fsync request finished: ~p", [Port]),
 	    {Caller, Starttime} = dict:fetch(Port, BusyPorts),
 	    Stoptime = os:timestamp(),
             statreport({fsync, Stoptime, Starttime}),
@@ -65,6 +70,7 @@ loop(IdlePorts, BusyPorts, Waiting) ->
                          NewWaiting)
 	    end;
 	stop ->
+            lager:debug("fsync stop request received"),
 	    lists:foreach(fun (Port) ->
                                   Port ! {self(), close}
                           end,
@@ -78,6 +84,7 @@ loop(IdlePorts, BusyPorts, Waiting) ->
 		    exit(normal) %% XXX exits when first port is closed
 	    end;
 	{'EXIT', Port, _Reason} when is_port(Port) ->
+            lager:debug("fsync port ~p exited, exiting", [Port]),
             %% XXX supervisor doesn't restart fsyncport, why?
 	    exit(port_terminated)
     end.
diff --git a/src/perm.erl b/src/perm.erl
index 466cc4f..c386d08 100644
--- a/src/perm.erl
+++ b/src/perm.erl
@@ -49,20 +49,27 @@ path_for_key(Rootdir, Key) ->
 
 -spec ensurefile(string(), binary(), binary()) -> ok | differ.
 ensurefile(Rootdir, Key, Content) ->
+    lager:debug("dir ~p key ~p", [Rootdir, Key]),
     {Dirs, Path} = path_for_key(Rootdir, Key),
     case readfile_and_verify(Path, Content) of
 	ok ->
-	    util:fsync([Path, Rootdir | Dirs]);
+            lager:debug("key ~p existed, fsync", [Key]),
+	    util:fsync([Path, Rootdir | Dirs]),
+            lager:debug("key ~p fsynced", [Key]);
         differ ->
+            lager:debug("key ~p existed, was different", [Key]),
             differ;
 	{error, enoent} ->
+            lager:debug("key ~p didn't exist, add", [Key]),
             util:check_error(make_dirs([Rootdir, Rootdir ++ "nursery/"]
                                        ++ Dirs),
                              makedir, "Error creating directory"),
             NurseryName = Rootdir ++ "nursery/" ++
                 util:tempfilename(hex:bin_to_hexstr(Key)),
             util:write_tempfile_and_rename(Path, NurseryName, Content),
-            util:fsync([Path, Rootdir | Dirs]);
+            lager:debug("key ~p added, fsync", [Key]),
+            util:fsync([Path, Rootdir | Dirs]),
+            lager:debug("key ~p fsynced", [Key]);
 	{error, Error} ->
             util:exit_with_error(Error, readfile, "Error reading file")
     end.
diff --git a/src/plop.erl b/src/plop.erl
index 84d0920..6e15781 100644
--- a/src/plop.erl
+++ b/src/plop.erl
@@ -109,6 +109,7 @@ handle_cast(_Request, State) ->
 
 handle_http_reply(State, {storage_sendentry_http, {OwnRequestId}},
                   StatusCode, Body) ->
+    lager:debug("http_reply: ~p", [Body]),
     {PropList} = (catch jiffy:decode(Body)),
     Result = proplists:get_value(<<"result">>, PropList),
     case dict:fetch(OwnRequestId, State#state.own_requests) of
@@ -216,6 +217,7 @@ send_storage_entrycommitted(URLBase, EntryHash, TreeLeafHash) ->
                   [], [{sync, false}]).
 
 store_at_all_nodes(Nodes, {LogEntry, TreeLeafHash, EntryHash}, From, State) ->
+    lager:debug("leafhash ~p", [TreeLeafHash]),
     OwnRequestId = make_ref(),
 
     Completion =
@@ -234,6 +236,7 @@ store_at_all_nodes(Nodes, {LogEntry, TreeLeafHash, EntryHash}, From, State) ->
                                    {From, Completion,
                                     storage_nodes_quorum()}}),
 
+    lager:debug("send requests to ~p", [Nodes]),
     RequestIds = [send_storage_sendentry(URLBase, LogEntry, TreeLeafHash)
                   || URLBase <- Nodes],
     PlopWithRequests =
@@ -259,6 +262,7 @@ handle_call({get, logid}, _From,
     {reply, LogID, Plop};
 
 handle_call({add, {LogEntry, TreeLeafHash, EntryHash}}, From, Plop) ->
+    lager:debug("add leafhash ~p", [TreeLeafHash]),
     case storage_nodes() of
         [] ->
             ok = db:add(TreeLeafHash, EntryHash, LogEntry, ht:size()),
diff --git a/src/storage.erl b/src/storage.erl
index 243cc6c..b966a12 100644
--- a/src/storage.erl
+++ b/src/storage.erl
@@ -12,6 +12,7 @@ newentries_path() ->
     Value.
 
 sendentry(SessionID, _Env, Input) ->
+    lager:debug("~p", [Input]),
     R = (catch case (catch jiffy:decode(Input)) of
                    {error, E} ->
                        html("sendentry: bad input:", E);
@@ -25,6 +26,7 @@ sendentry(SessionID, _Env, Input) ->
                          jiffy:encode(
                            {[{result, <<"ok">>}]}))
                end),
+    lager:debug("result ~p", [R]),
     deliver(SessionID, R).
 
 entrycommitted(SessionID, _Env, Input) ->