From b968cb1330ecb13f26e35d948c0511882b89ab2a Mon Sep 17 00:00:00 2001 From: Magnus Ahltorp Date: Fri, 24 Oct 2014 15:32:58 +0200 Subject: Added lager for logging --- src/db.erl | 2 ++ src/fsyncport.erl | 7 +++++++ src/perm.erl | 11 +++++++++-- src/plop.erl | 4 ++++ src/storage.erl | 2 ++ 5 files changed, 24 insertions(+), 2 deletions(-) (limited to 'src') 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) -> -- cgit v1.1