wip: add 'protocol' logging, only implemented for HTTP currently (TSU…

…N-164)

include/ts_http.hrl

@@ -62,7 +62,7 @@
 -record(http, {content_length= 0,  % HTTP header: content length
                body_size     = 0,  % current size of body,
                chunk_toread  = -1, % chunk data to be read (-1 = not chunked, -2 = not chunked, but last response was)
-               status        = none, % HTTP resp. status :200, etc. 'none'
+               status        = {none,none}, % HTTP resp. status :200, etc. 'none'
                                      % if no current cnx.
                close         = false, % true if HTTP/1.0 or 'connection: close'
                                      % has been received

src/tsung/ts_client.erl

@@ -902,9 +902,9 @@ handle_data_msg(Data, State=#state_rcv{request=Req}) when Req#ts_request.ack==no
     ts_mon:rcvmes({State#state_rcv.dump, self(), Data}),
     {State, []};
 
-handle_data_msg(Data,State=#state_rcv{request=Req,clienttype=Type,maxcount=MaxCount})
+handle_data_msg(Data,State=#state_rcv{dump=Dump,request=Req,id=Id,clienttype=Type,maxcount=MaxCount})
   when Req#ts_request.ack==parse->
-    ts_mon:rcvmes({State#state_rcv.dump, self(), Data}),
+    ts_mon:rcvmes({Dump, self(), Data}),
 
     {NewState, Opts, Close} = Type:parse(Data, State),
     NewBuffer=set_new_buffer(NewState, Data),
@@ -913,10 +913,11 @@ handle_data_msg(Data,State=#state_rcv{request=Req,clienttype=Type,maxcount=MaxCo
     case NewState#state_rcv.ack_done of
         true ->
             ?DebugF("Response done:~p~n", [NewState#state_rcv.datasize]),
+            Type:dump(Dump,{Req,NewState#state_rcv.session,Id,
+                            NewState#state_rcv.host,NewState#state_rcv.datasize}),
             {PageTimeStamp, DynVars} = update_stats(NewState#state_rcv{buffer=NewBuffer}),
             MatchArgs={NewState#state_rcv.count, MaxCount,
-                       NewState#state_rcv.session_id,
-                       NewState#state_rcv.id},
+                       NewState#state_rcv.session_id, Id},
             NewDynVars=ts_dynvars:merge(DynVars,(NewState#state_rcv.dyndata)#dyndata.dynvars),
             NewCount  =ts_search:match(Req#ts_request.match,NewBuffer,MatchArgs,NewDynVars),
             NewDynData=(NewState#state_rcv.dyndata)#dyndata{dynvars=NewDynVars},

src/tsung/ts_http.erl

@@ -33,6 +33,7 @@
          add_dynparams/4,
          get_message/1,
          session_defaults/0,
+         dump/2,
          parse/2,
          parse_config/2,
          decode_buffer/2,
@@ -66,35 +67,62 @@ decode_buffer(Buffer,#http{chunk_toread = -1, compressed={_,Val}}) ->
     {Headers, CompressedBody} = split_body(Buffer),
     Body = decompress(CompressedBody, Val),
     << Headers/binary,  "\r\n\r\n", Body/binary >>;
-decode_buffer(Buffer,Http=#http{compressed={_,Comp}})->
+decode_buffer(Buffer,#http{compressed={_,Comp}})->
     {Headers, Body} = decode_chunk(Buffer),
     ?DebugF("body is ~p~n",[Body]),
     RealBody = decompress(Body, Comp),
     ?DebugF("decoded buffer: ~p",[RealBody]),
     <<Headers/binary, "\r\n\r\n", RealBody/binary >>.
 
+dump(protocol,{#ts_request{param=HttpReq},HttpResp,UserId,Server,Size})->
+    Status = integer_to_list(element(2,HttpResp#http.status)),
+    Match = case get(last_match) of
+                undefined ->
+                    "";
+                {count, Val} ->
+                    put(last_match, undefined),
+                    atom_to_list(Val)
+            end,
+    Error = case get(protocol_error) of
+                undefined ->
+                    "";
+                Err ->
+                    put(protocol_error, undefined),
+                    atom_to_list(Err)
+            end,
+    Data=ts_utils:join(":",[integer_to_list(UserId),
+                            atom_to_list(HttpReq#http_request.method), Server,
+                            get(last_url), Status,integer_to_list(Size),Match, Error]),
+    ts_mon:dump({protocol, self(), Data });
+dump(_,_) ->
+    ok.
+
+
 %%----------------------------------------------------------------------
 %% Function: get_message/21
 %% Purpose: Build a message/request ,
 %% Args:    #http_request
 %% Returns: binary
 %%----------------------------------------------------------------------
-get_message(Req=#http_request{method=get}) ->
+get_message(Req=#http_request{url=URL}) ->
+    put(last_url,URL),
+    get_message2(Req).
+get_message2(Req=#http_request{method=get}) ->
     ts_http_common:http_no_body(?GET, Req);
 
-get_message(Req=#http_request{method=head}) ->
+get_message2(Req=#http_request{method=head}) ->
     ts_http_common:http_no_body(?HEAD, Req);
 
-get_message(Req=#http_request{method=delete}) ->
+get_message2(Req=#http_request{method=delete}) ->
     ts_http_common:http_no_body(?DELETE, Req);
 
-get_message(Req=#http_request{method=post}) ->
+get_message2(Req=#http_request{method=post}) ->
     ts_http_common:http_body(?POST, Req);
 
-get_message(Req=#http_request{method=options}) ->
+get_message2(Req=#http_request{method=options}) ->
     ts_http_common:http_no_body(?OPTIONS, Req);
 
-get_message(Req=#http_request{method=put}) ->
+get_message2(Req=#http_request{method=put}) ->
     ts_http_common:http_body(?PUT, Req).
 
 %%----------------------------------------------------------------------
@@ -219,7 +247,7 @@ decode_chunk_header(<<CRLF:4/binary, Data/binary >>,Headers) when CRLF == << "\r
 decode_chunk_header(<<CRLF:1/binary, Data/binary >>, Head) ->
     decode_chunk_header(Data, <<Head/binary, CRLF/binary>> ).
 
-decode_chunk_size(<< >>, Headers, Body,Digits) ->
+decode_chunk_size(<< >>, Headers, Body, _Digits) ->
     {Headers, Body};
 decode_chunk_size(<<Head:2/binary >>, Headers, Body, <<>>) when Head ==  << "\r\n" >> ->
     %last CRLF, remove

src/tsung/ts_http_common.erl

@@ -212,7 +212,7 @@ matchdomain_url(Cookie, Host, URL) ->
 parse(closed, State=#state_rcv{session=Http}) ->
     {State#state_rcv{session=reset_session(Http), ack_done = true}, [], true};
 
-parse(Data, State=#state_rcv{session=HTTP}) when HTTP#http.status  == none;
+parse(Data, State=#state_rcv{session=HTTP}) when element(1,HTTP#http.status)  == none;
                                                  HTTP#http.partial == true ->
 
     List = binary_to_list(Data),
@@ -239,12 +239,12 @@ parse(Data, State=#state_rcv{session=HTTP}) when HTTP#http.status  == none;
             {State#state_rcv{session= Http, ack_done = false,
                              datasize = TotalSize,
                              dyndata= DynData}, [], true};
-        {ok, Http=#http{status=100}, _} -> % Status 100 Continue, ignore.
+        {ok, Http=#http{status={100,_}}, _} -> % Status 100 Continue, ignore.
             %% FIXME: not tested
             {State#state_rcv{ack_done=false,session=reset_session(Http)},[],false};
         {ok, Http, Tail} ->
             DynData = concat_cookies(Http#http.cookie, State#state_rcv.dyndata),
-            check_resp_size(Http, length(Tail), DynData, State#state_rcv{acc=[]}, TotalSize)
+            check_resp_size(Http, length(Tail), DynData, State#state_rcv{acc=[]}, TotalSize, State#state_rcv.dump)
     end;
 
 %% continued chunked transfer
@@ -280,20 +280,20 @@ parse(Data, State) ->
 %% Returns: {NewState= record(state_rcv), SockOpts, Close}
 %%----------------------------------------------------------------------
 check_resp_size(Http=#http{content_length=CLength, close=Close}, CLength,
-                DynData, State, DataSize) ->
+                DynData, State, DataSize, _Dump) ->
     %% end of response
     {State#state_rcv{session= reset_session(Http), ack_done = true,
                      datasize = DataSize,
                      dyndata= DynData}, [], Close};
 check_resp_size(Http=#http{content_length=CLength, close = Close},
-                BodySize, DynData, State, DataSize) when BodySize > CLength ->
+                BodySize, DynData, State, DataSize, Dump) when BodySize > CLength ->
     ?LOGF("Error: HTTP Body (~p)> Content-Length (~p) !~n",
           [BodySize, CLength], ?ERR),
-    ts_mon:add({ count, error_http_bad_content_length }),
+    log_error(Dump, error_http_bad_content_length),
     {State#state_rcv{session= reset_session(Http), ack_done = true,
                      datasize = DataSize,
                      dyndata= DynData}, [], Close};
-check_resp_size(Http, BodySize, DynData, State, DataSize) ->
+check_resp_size(Http, BodySize, DynData, State, DataSize,_Dump) ->
     %% need to read more data
     {State#state_rcv{session  = Http#http{ body_size=BodySize},
                      ack_done = false,
@@ -342,10 +342,11 @@ read_chunk(<<Char:1/binary, Data/binary>>, State=#state_rcv{session=Http}, Int,
         read_chunk(Data, State, Int, Acc+1);
     _Other ->
             ?LOGF("Unexpected error while parsing chunk ~p~n", [_Other] ,?WARN),
-            ts_mon:add({count, error_http_unexpected_chunkdata}),
+            log_error(State#state_rcv.dump, error_http_unexpected_chunkdata),
             {State#state_rcv{session= reset_session(Http), ack_done = true}, []}
     end.
 
+
 %%----------------------------------------------------------------------
 %% Func: read_chunk_data/4
 %% Purpose: read 'Int' bytes of data
@@ -534,11 +535,11 @@ http_method(Method) ->
 %% Purpose: Parse HTTP status
 %% Returns: #http
 %%--------------------------------------------------------------------
-parse_status([A,B,C|_],  Http) ->
+parse_status([A,B,C|_], Http=#http{status={Prev,_}}) ->
     Status=list_to_integer([A,B,C]),
     ?DebugF("HTTP Status ~p~n",[Status]),
     ts_mon:add({ count, Status }),
-    Http#http{status=Status}.
+    Http#http{status={Status,Prev}}.
 
 %%--------------------------------------------------------------------
 %% Func: parse_line/3
@@ -612,8 +613,13 @@ get_line([], _, _) -> %% Headers are fragmented ... We need more data
     {more}.
 
 %% we need to keep the compressed value of the current request
-reset_session(#http{compressed={Current,_},chunk_toread=Val}) when Val > -1 ->
-    #http{compressed={false,Current}, chunk_toread=-2} ;
-reset_session(#http{compressed={Current,_}} ) ->
-    #http{compressed={false,Current}}.
-
+reset_session(#http{status={Status,_},compressed={Current,_},chunk_toread=Val}) when Val > -1 ->
+    #http{compressed={false,Current}, chunk_toread=-2, status={none,Status}} ;
+reset_session(#http{compressed={Current,_}, status={Status,_}} ) ->
+    #http{compressed={false,Current}, status={none,Status}}.
+
+log_error(protocol,Error) ->
+    put(protocol_error,Error),
+    log_error2(protocol,Error).
+log_error2(_,Error)->
+    ts_mon:add({count, Error}).

src/tsung/ts_utils.erl

@@ -42,7 +42,7 @@
          check_sum/3, check_sum/5, clean_str/1, file_to_list/1, term_to_list/1,
          decode_base64/1, encode_base64/1, to_lower/1, release_is_newer_or_eq/1,
          randomstr/1,urandomstr/1,urandomstr_noflat/1, eval/1, list_to_number/1,
-         time2sec/1, read_file_raw/1, init_seed/1, jsonpath/2, pmap/2,
+         time2sec/1, time2sec_hires/1, read_file_raw/1, init_seed/1, jsonpath/2, pmap/2,
          concat_atoms/1
         ]).
 
@@ -175,6 +175,9 @@ now_sec() ->
 time2sec({MSec, Seconds, _}) ->
     Seconds+1000000*MSec.
 
+time2sec_hires({MSec, Seconds, MuSec}) ->
+    Seconds+1000000*MSec+MuSec/1000000.
+
 %%----------------------------------------------------------------------
 %% Func: add_time/2
 %% Purpose: add given Seconds to given Time (same format as now())

src/tsung_controller/ts_config.erl

@@ -87,7 +87,8 @@ parse(Element = #xmlElement{parents = [], attributes=Attrs}, Conf=#config{}) ->
     DumpType = case Dump of
                    "false" -> none;
                    "true"  -> full;
-                   "light" -> light
+                   "light" -> light;
+                   "protocol" -> protocol
                end,
     lists:foldl(fun parse/2,
                 Conf#config{dump= DumpType, stats_backend=BackEnd,

src/tsung_controller/ts_config_server.erl

@@ -723,8 +723,8 @@ local_launcher([Host],LogDir,Config) ->
     %% set the application spec (read the app file and update some env. var.)
     {ok, {_,_,AppSpec}} = load_app(tsung),
     {value, {env, OldEnv}} = lists:keysearch(env, 1, AppSpec),
-    NewEnv = [ {dump,atom_to_list(?config(dump))},
-               {debug_level,integer_to_list(?config(debug_level))},
+    NewEnv = [ {dump,?config(dump)},
+               {debug_level,?config(debug_level)},
                {log_file,LogDirEnc}],
 
     RepKeyFun = fun(Tuple, List) ->  lists:keyreplace(element(1, Tuple), 1, List, Tuple) end,

src/tsung_controller/ts_mon.erl

@@ -44,7 +44,7 @@
 %% External exports
 -export([start/1, stop/0, newclient/1, endclient/1, sendmes/1, add/2,
          start_clients/1, abort/0, status/0, rcvmes/1, add/1, dumpstats/0,
-         add_match/2
+         add_match/2, dump/1
         ]).
 
 %% gen_server callbacks
@@ -106,8 +106,9 @@ add(nocache,Data) ->
 add(Data) ->
     ts_mon_cache:add(Data).
 
-add_match(Data,{UserId,SessionId,RequestId}) ->
+add_match(Data=[Head|_],{UserId,SessionId,RequestId}) ->
     TimeStamp=now(),
+    put(last_match,Head),
     ts_mon_cache:add_match(Data,{UserId,SessionId,RequestId,TimeStamp}).
 
 status() ->
@@ -125,16 +126,21 @@ newclient({Who, When}) ->
 endclient({Who, When, Elapsed}) ->
     gen_server:cast({global, ?MODULE}, {endclient, Who, When, Elapsed}).
 
-sendmes({none, _, _}) ->
-    skip;
+sendmes({none, _, _})       -> skip;
+sendmes({protocol, _, _})   -> skip;
 sendmes({_Type, Who, What}) ->
     gen_server:cast({global, ?MODULE}, {sendmsg, Who, now(), What}).
 
-rcvmes({none, _, _})-> skip;
-rcvmes({_, _, closed}) -> skip;
+rcvmes({none, _, _})    -> skip;
+rcvmes({protocol, _, _})-> skip;
+rcvmes({_, _, closed})  -> skip;
 rcvmes({_Type, Who, What})  ->
     gen_server:cast({global, ?MODULE}, {rcvmsg, Who, now(), What}).
 
+dump({none, _, _})-> skip;
+dump({Type, Who, What})  ->
+    gen_server:cast({global, ?MODULE}, {dump, Who, now(), What}).
+
 
 %%%----------------------------------------------------------------------
 %%% Callback functions from gen_server
@@ -235,7 +241,8 @@ handle_cast({newclient, Who, When}, State=#state{stats=Stats}) ->
     NewStats = Stats#stats{users_count=OldCount+1},
 
     case State#state.type of
-        none -> ok;
+        none     -> ok;
+        protocol -> ok;
         _ ->
             io:format(State#state.dumpfile,"NewClient:~w:~p~n",[When, Who]),
             io:format(State#state.dumpfile,"load:~w~n",[Clients])
@@ -258,6 +265,8 @@ handle_cast({endclient, Who, When, Elapsed}, State=#state{stats=Stats}) ->
     case State#state.type of
         none ->
             skip;
+        protocol ->
+            skip;
         _Type ->
             io:format(State#state.dumpfile,"EndClient:~w:~p~n",[When, Who]),
             io:format(State#state.dumpfile,"load:~w~n",[Clients])
@@ -285,14 +294,18 @@ handle_cast({sendmsg, Who, When, What}, State = #state{type=light,dumpfile=Log})
     io:format(Log,"Send:~w:~w:~-44s~n",[When,Who, binary_to_list(What)]),
     {noreply, State};
 
-handle_cast({sendmsg, Who, When, What}, State=#state{dumpfile=Log}) when is_binary(What)->
+handle_cast({sendmsg, Who, When, What}, State=#state{type=full,dumpfile=Log}) when is_binary(What)->
     io:format(Log,"Send:~w:~w:~s~n",[When,Who,binary_to_list(What)]),
     {noreply, State};
 
-handle_cast({sendmsg, Who, When, What}, State=#state{dumpfile=Log}) ->
+handle_cast({sendmsg, Who, When, What}, State=#state{type=full,dumpfile=Log}) ->
     io:format(Log,"Send:~w:~w:~p~n",[When,Who,What]),
     {noreply, State};
 
+handle_cast({dump, Who, When, What}, State=#state{dumpfile=Log}) ->
+    io:format(Log,"~w:~w:~s~n",[ts_utils:time2sec_hires(When),Who,What]),
+    {noreply, State};
+
 handle_cast({rcvmsg, _, _, _}, State = #state{type=none}) ->
     {noreply, State};
 
@@ -303,11 +316,11 @@ handle_cast({rcvmsg, Who, When, What}, State = #state{type=light, dumpfile=Log})
     io:format(Log,"Recv:~w:~w:~-44p~n",[When,Who, What]),
     {noreply, State};
 
-handle_cast({rcvmsg, Who, When, What}, State=#state{dumpfile=Log}) when is_binary(What)->
+handle_cast({rcvmsg, Who, When, What}, State=#state{type=full,dumpfile=Log}) when is_binary(What)->
     io:format(Log, "Recv:~w:~w:~s~n",[When,Who,binary_to_list(What)]),
     {noreply, State};
 
-handle_cast({rcvmsg, Who, When, What}, State=#state{dumpfile=Log}) ->
+handle_cast({rcvmsg, Who, When, What}, State=#state{type=full,dumpfile=Log}) ->
     io:format(Log, "Recv:~w:~w:~p~n",[When,Who,What]),
     {noreply, State};
 

tsung-1.0.dtd

@@ -10,7 +10,7 @@
 <!ELEMENT organisation (#PCDATA)>
 
 <!ATTLIST tsung
-     dumptraffic (true | false | light) "false"
+     dumptraffic (true | false | light | protocol) "false"
      backend     (text | rrdtool | fullstats) "text"
      loglevel    (emergency|critical|error|warning|notice|info|debug) "notice"
      version     NMTOKEN #IMPLIED>