[snmp] Improving ATL handling of corrupt logs

When converting an Audit Trail Log to text a corrupt
log entry could cause the entire conversion to fail.
Also, for a log with sequence numbers, failing to
decode a log entry would cause the conversion to fail
(not because of the failed decode, but because of the
failure to write the error message).

OTP-11453

1 files changed, 203 insertions, 73 deletions

diff --git a/lib/snmp/src/misc/snmp_log.erl b/lib/snmp/src/misc/snmp_log.erl
index a8c5df0b64..a365e8c8ed 100644
--- a/lib/snmp/src/misc/snmp_log.erl
+++ b/lib/snmp/src/misc/snmp_log.erl
@@ -1,7 +1,7 @@
 %% 
 %% %CopyrightBegin%
 %%
-%% Copyright Ericsson AB 1997-2012. All Rights Reserved.
+%% Copyright Ericsson AB 1997-2013. All Rights Reserved.
 %%
 %% The contents of this file are subject to the Erlang Public License,
 %% Version 1.1, (the "License"); you may not use this file except in
@@ -16,6 +16,7 @@
 %%
 %% %CopyrightEnd%
 %% 
+%% 
 
 -module(snmp_log).
 
@@ -397,6 +398,8 @@ log_to_txt(Log, FileName, Dir, Mibs, TextFile, Start, Stop)
 	    [Log, FileName, Dir, Mibs, TextFile, Start, Stop]),
     File = filename:join(Dir, FileName),
     Converter = fun(L) ->
+			?vtrace("log_to_txt:fun -> entry with"
+				"~n   L: ~p", [L]),
 			do_log_to_file(L, TextFile, Mibs, Start, Stop)
 		end,
     log_convert(Log, File, Converter).
@@ -422,6 +425,8 @@ log_to_io(Log, FileName, Dir, Mibs, Start, Stop)
 	    [Log, FileName, Dir, Mibs, Start, Stop]),
     File = filename:join(Dir, FileName),
     Converter = fun(L) ->
+			?vtrace("log_to_io:fun -> entry with"
+				"~n   L: ~p", [L]),
 			do_log_to_io(L, Mibs, Start, Stop)
 		end,
     log_convert(Log, File, Converter).
@@ -439,22 +444,25 @@ log_convert(Log, File, Converter) ->
     do_log_convert(Log, File, Converter).
 
 do_log_convert(Log, File, Converter) ->
-    %% ?vtrace("do_log_converter -> entry with"
-    %% 	    "~n   Log:  ~p"
-    %% 	    "~n   File: ~p"
-    %% 	    "~n   disk_log:info(Log): ~p", [Log, File, disk_log:info(Log)]),
+    ?vtrace("do_log_converter -> entry with"
+    	    "~n   Log:  ~p"
+    	    "~n   File: ~p", [Log, File]),
+    Verbosity = get(verbosity), 
     {Pid, Ref} = 
 	erlang:spawn_monitor(
 	  fun() ->
+		  put(sname, "LOG-CONVERTER"), 
+		  put(verbosity, Verbosity), 
+		  erlang:process_flag(trap_exit, true), 
+		  ?vlog("begin converting", []),
 		  Result = do_log_convert2(Log, File, Converter),
+		  ?vlog("convert result: ~p", [Result]),
 		  exit(Result)
 	  end),
     receive 
 	{'DOWN', Ref, process, Pid, Result} ->
-	    %% ?vtrace("do_log_converter -> received result"
-	    %% 	    "~n   Result: ~p"
-	    %% 	    "~n   disk_log:info(Log): ~p", 
-	    %% 	    [Result, disk_log:info(Log)]),
+	    ?vtrace("do_log_converter -> received result"
+	    	    "~n   Result: ~p", [Result]),
 	    Result
     end.
     
@@ -462,19 +470,31 @@ do_log_convert2(Log, File, Converter) ->
     %% First check if the caller process has already opened the
     %% log, because if we close an already open log we will cause
     %% a runtime error.
+    ?vtrace("do_log_convert2 -> entry - check if owner", []),
     case is_owner(Log) of
 	true ->
+	    ?vtrace("do_log_convert2 -> owner - now convert", []),
 	    Converter(Log);
 	false ->
 	    %% Not yet member of the ruling party, apply for membership...
+	    ?vtrace("do_log_convert2 -> not owner - open", []),
 	    case log_open(Log, File) of
 		{ok, _} ->
+		    ?vdebug("do_log_convert2 -> opened - now convert", []),
 		    Res = Converter(Log),
+		    ?vtrace("do_log_convert2 -> converted - now close", []),
 		    disk_log:close(Log),
+		    ?vtrace("do_log_convert2 -> closed - done", []),
 		    Res;
 		{error, {name_already_open, _}} ->
-                    Converter(Log);
+		    ?vdebug("do_log_convert2 -> "
+			    "already opened - now convert", []),
+                    Res = Converter(Log),
+		    ?vtrace("do_log_convert2 -> converted - done", []),
+		    Res;
                 {error, Reason} ->
+		    ?vinfo("do_log_convert2 -> failed open: "
+			    "~n   Reason: ~p", [Reason]),
                     {error, {Log, Reason}}
 	    end
     end.
@@ -483,50 +503,93 @@ do_log_convert2(Log, File, Converter) ->
 %% -- do_log_to_text ---
 
 do_log_to_file(Log, TextFile, Mibs, Start, Stop) ->
+    ?vtrace("do_log_to_txt -> entry with"
+	    "~n   Log:      ~p"
+	    "~n   TextFile: ~p"
+	    "~n   Start:    ~p"
+	    "~n   Stop:     ~p", [Log, TextFile, Start, Stop]),
     case file:open(TextFile, [write]) of
         {ok, Fd} ->
+	    ?vtrace("do_log_to_txt -> outfile created - create mini MIB", []),
             MiniMib = snmp_mini_mib:create(Mibs),
+	    ?vtrace("do_log_to_txt -> mini-MIB created - begin conversion", []),
 	    Write = fun(X) -> 
+			    ?vtrace("do_log_to_txt:fun -> "
+				    "entry - try format", []),
 			    case format_msg(X, MiniMib, Start, Stop) of
 				{ok, S} ->
+				    ?vtrace("do_log_to_txt:fun -> "
+					    "formated - now write", []),
 				    io:format(Fd, "~s", [S]);
 				_ ->
+				    ?vdebug("do_log_to_txt:fun -> "
+					    "format failed", []),
 				    ok
 			    end
 		    end,
             Res = (catch loop(disk_log:chunk(Log, start), Log, Write)),
+	    ?vtrace("do_log_to_txt -> converted - now delete mini-MIB", []),
 	    snmp_mini_mib:delete(MiniMib), 
+	    ?vtrace("do_log_to_txt -> "
+		    "mini-MIB closed - now close output file", []),
             file:close(Fd),
+	    ?vtrace("do_log_to_txt -> done", []),
             Res;
         {error, Reason} ->
+	    ?vinfo("failed opening output file: "
+		   "~n   TestFile: ~p"
+		   "~n   Reason:   ~p", [TextFile, Reason]),
             {error, {TextFile, Reason}}
     end.
 
 
 do_log_to_io(Log, Mibs, Start, Stop) ->
+    ?vtrace("do_log_to_io -> entry with"
+	    "~n   Log:   ~p"
+	    "~n   Mibs:  ~p"
+	    "~n   Start: ~p"
+	    "~n   Stop:  ~p", [Log, Mibs, Start, Stop]),
     MiniMib = snmp_mini_mib:create(Mibs),
+    ?vtrace("do_log_to_io -> mini-MIB created - begin conversion", []),
     Write = fun(X) -> 
+		    ?vtrace("do_log_to_io:fun -> entry", []),
 		    case format_msg(X, MiniMib, Start, Stop) of
 			{ok, S} ->
+			    ?vtrace("do_log_to_io:fun -> "
+				    "formated - now write", []),
 			    io:format("~s", [S]);
 			_ ->
+			    ?vdebug("do_log_to_io:fun -> "
+				    "format failed", []),
 			    ok
 		    end
 	    end,
     (catch loop(disk_log:chunk(Log, start), Log, Write)),
+    ?vtrace("do_log_to_io -> converted - now delete mini-MIB", []),
     snmp_mini_mib:delete(MiniMib),
+    ?vtrace("do_log_to_io -> done", []),
     ok.
 
 
 loop(eof, _Log, _Write) ->
+    ?vtrace("loop -> entry when eof", []),
     ok;
-loop({error, _} = Error, _Log, _Write) ->
+loop({error, _Reason} = Error, _Log, _Write) ->
+    ?vtrace("loop -> entry with error"
+	    "~n   Reason: ~p", [_Reason]),
     Error;
 loop({Cont, Terms}, Log, Write) ->
-    case (catch lists:foreach(Write, Terms)) of
+    ?vtrace("loop -> entry with terms"
+	    "~n   Cont:          ~p"
+	    "~n   length(Terms): ~p", [Cont, length(Terms)]), 
+   case (catch lists:foreach(Write, Terms)) of
 	{'EXIT', Reason} ->
+	    ?vtrace("loop -> failure while writing terms"
+		    "~n   Reason: ~p", [Reason]),
 	    {error, Reason};
-	_ ->
+	_X ->
+	   ?vtrace("loop -> terms written"
+		   "~n   X: ~p", [_X]),
 	    loop(disk_log:chunk(Log, Cont), Log, Write)
     end;
 loop({Cont, Terms, BadBytes}, Log, Write) ->
@@ -539,6 +602,8 @@ loop({Cont, Terms, BadBytes}, Log, Write) ->
 	    loop(disk_log:chunk(Log, Cont), Log, Write)
     end;
 loop(Error, _Log, _Write) ->
+    ?vtrace("loop -> entry with unknown"
+	    "~n   Error: ~p", [Error]),
     Error.
 
 
@@ -553,14 +618,17 @@ format_msg(Entry, Mib, Start, Stop) ->
 
 %% This is an old-style entry, that never had the sequence-number
 do_format_msg({Timestamp, Packet, {Addr, Port}}, Mib) ->
+    ?vdebug("do_format_msg -> old style log entry", []),
     do_format_msg(Timestamp, Packet, Addr, Port, Mib);
 
 %% This is the format without sequence-number
 do_format_msg({Timestamp, Packet, Addr, Port}, Mib) ->
+    ?vdebug("do_format_msg -> log entry without seqno", []),
     do_format_msg(Timestamp, Packet, Addr, Port, Mib);
 
 %% This is the format with sequence-number
 do_format_msg({Timestamp, SeqNo, Packet, Addr, Port}, Mib) ->
+    ?vdebug("do_format_msg -> log entry with seqno", []),
     do_format_msg(Timestamp, SeqNo, Packet, Addr, Port, Mib);
 
 %% This is crap...
@@ -568,103 +636,165 @@ do_format_msg(_, _) ->
     format_tab("** unknown entry in log file\n\n", []).
 
 do_format_msg(TimeStamp, {V3Hdr, ScopedPdu}, Addr, Port, Mib) ->
+    ?vtrace("do_format_msg -> entry with"
+	    "~n   Timestamp: ~p"
+	    "~n   Addr:      ~p"
+	    "~n   Port:      ~p"
+	    "~n   => Try decode scoped pdu", 
+	    [TimeStamp, Addr, Port]),
     case (catch snmp_pdus:dec_scoped_pdu(ScopedPdu)) of
 	ScopedPDU when is_record(ScopedPDU, scopedPdu) -> 
+	    ?vtrace("do_format_msg -> scoped pdu decoded"
+		    "~n   ScopedPDU: ~p", [ScopedPDU]),
 	    Msg = #message{version = 'version-3',
 			   vsn_hdr = V3Hdr,
 			   data    = ScopedPDU},
 	    f(ts2str(TimeStamp), "", Msg, Addr, Port, Mib);
+
 	{'EXIT', Reason} ->
-	    format_tab("** error in log file at ~s from ~p:~w ~p\n\n", 
+	    ?vinfo("Failed decoding scoped pdu: "
+		   "~n   V3Hdr:     ~w"
+		   "~n   ScopedPdu: ~w"
+		   "~n   Reason:    ~p", [V3Hdr, ScopedPdu, Reason]),
+	    format_tab("** error in log file at ~s from ~s:~w ~p\n\n", 
 		       [ts2str(TimeStamp), ip(Addr), Port, Reason])
     end;
+
 do_format_msg(TimeStamp, Packet, Addr, Port, Mib) ->
+    ?vtrace("do_format_msg -> entry with"
+	    "~n   Timestamp: ~p"
+	    "~n   Addr:      ~p"
+	    "~n   Port:      ~p"
+	    "~n   => Try decode packet", 
+	    [TimeStamp, Addr, Port]),
     case (catch snmp_pdus:dec_message(binary_to_list(Packet))) of
-	Msg when is_record(Msg, message) ->
+	#message{data = Data} = Msg when (is_record(Data, scopedPdu) orelse 
+					  is_record(Data, pdu) orelse 
+					  is_record(Data, trappdu)) ->
+	    ?vtrace("do_format_msg -> packet decoded"
+		    "~n   Msg: ~p", [Msg]),
 	    f(ts2str(TimeStamp), "", Msg, Addr, Port, Mib);
+
+	#message{version = Vsn, 
+		 vsn_hdr = VsnHdr} = Msg ->
+	    ?vinfo("Message not fully decoded: "
+		   "~n   Msg: ~p", [Msg]),
+	    Reason = 
+		lists:flatten(
+		  io_lib:format("Message not fully decoded: "
+				"Vsn = ~p, VsnHdr = ~w", [Vsn, VsnHdr])),
+	    format_tab("** error in log file ~s from ~s:~w => "
+		       "\n   ~s\n\n", 
+		       [ts2str(TimeStamp), ip(Addr), Port, Reason]);
+
 	{'EXIT', Reason} ->
+	    ?vinfo("Failed decoding packet: "
+		   "~n   Packet: ~w"
+		   "~n   Reason: ~p", [Packet, Reason]),
 	    format_tab("** error in log file ~p\n\n", [Reason])
     end.
     
 do_format_msg(TimeStamp, SeqNo, {V3Hdr, ScopedPdu}, Addr, Port, Mib) ->
+    ?vtrace("do_format_msg -> entry with"
+	    "~n   Timestamp: ~p"
+	    "~n   SeqNo:     ~p"
+	    "~n   Addr:      ~p"
+	    "~n   Port:      ~p"
+	    "~n   => Try decode scoped pdu", 
+	    [TimeStamp, SeqNo, Addr, Port]),
     case (catch snmp_pdus:dec_scoped_pdu(ScopedPdu)) of
 	ScopedPDU when is_record(ScopedPDU, scopedPdu) -> 
+	    ?vtrace("do_format_msg -> scoped pdu decoded"
+		    "~n   ScopedPDU: ~p", [ScopedPDU]),
 	    Msg = #message{version = 'version-3',
 			   vsn_hdr = V3Hdr,
 			   data    = ScopedPDU},
 	    f(ts2str(TimeStamp), sn2str(SeqNo), Msg, Addr, Port, Mib);
+
 	{'EXIT', Reason} ->
-	    format_tab("** error in log file at ~s from ~p:~w ~p\n\n", 
+	    ?vinfo("Failed decoding scoped pdu: "
+		   "~n   V3Hdr:     ~w"
+		   "~n   ScopedPdu: ~w"
+		   "~n   Reason:    ~p", [V3Hdr, ScopedPdu, Reason]),
+	    format_tab("** error in log file at ~s~s from ~s:~w ~p\n\n", 
 		       [ts2str(TimeStamp), sn2str(SeqNo), 
 			ip(Addr), Port, Reason])
     end;
 do_format_msg(TimeStamp, SeqNo, Packet, Addr, Port, Mib) ->
+    ?vtrace("do_format_msg -> entry with"
+	    "~n   Timestamp: ~p"
+	    "~n   SeqNo:     ~p"
+	    "~n   Addr:      ~p"
+	    "~n   Port:      ~p"
+	    "~n   => Try decode message", 
+	    [TimeStamp, SeqNo, Addr, Port]),
     case (catch snmp_pdus:dec_message(binary_to_list(Packet))) of
-	Msg when is_record(Msg, message) ->
+	#message{data = Data} = Msg when (is_record(Data, scopedPdu) orelse 
+					  is_record(Data, pdu) orelse 
+					  is_record(Data, trappdu)) ->
+	    ?vtrace("do_format_msg -> message decoded"
+		    "~n   Msg: ~p", [Msg]),
 	    f(ts2str(TimeStamp), sn2str(SeqNo), Msg, Addr, Port, Mib);
+
+	#message{version = Vsn, 
+		 vsn_hdr = VsnHdr} = Msg ->
+	    ?vinfo("Message not fully decoded: "
+		   "~n   Msg: ~p", [Msg]),
+	    Reason = 
+		lists:flatten(
+		  io_lib:format("Message not fully decoded: "
+				"Vsn = ~p, VsnHdr = ~w", [Vsn, VsnHdr])),
+	    format_tab("** error in log file ~s~s from ~s:~w => "
+		       "\n   ~s\n\n", 
+		       [ts2str(TimeStamp), sn2str(SeqNo), 
+			ip(Addr), Port, Reason]);
+
 	{'EXIT', Reason} ->
-	    format_tab("** error in log file ~s from ~p:~w ~p\n\n", 
+	    ?vinfo("Failed decoding packet: "
+		   "~n   Packet: ~w"
+		   "~n   Reason: ~p", [Packet, Reason]),
+	    format_tab("** error in log file ~s (~s) from ~s:~w ~p\n\n", 
 		       [ts2str(TimeStamp), sn2str(SeqNo), 
 			ip(Addr), Port, Reason])
     end.
     
     
-%% format_msg({TimeStamp, {V3Hdr, ScopedPdu}, {Addr, Port}}, 
-%% 	   Mib, Start, Stop) ->
-%%     format_msg({TimeStamp, {V3Hdr, ScopedPdu}, Addr, Port}, 
-%% 	      Mib, Start, Stop);
-%% format_msg({TimeStamp, {V3Hdr, ScopedPdu}, Addr, Port}, 
-%% 	  Mib, Start, Stop) ->
-%%     case timestamp_filter(TimeStamp, Start, Stop) of
-%%         true ->
-%%             case (catch snmp_pdus:dec_scoped_pdu(ScopedPdu)) of
-%%                 ScopedPDU when record(ScopedPDU, scopedPdu) -> 
-%%                     Msg = #message{version = 'version-3',
-%%                                    vsn_hdr = V3Hdr,
-%%                                    data    = ScopedPDU},
-%%                     f(ts2str(TimeStamp), Msg, Addr, Port, Mib);
-%%                 {'EXIT', Reason} ->
-%%                     format_tab("** error in log file at ~s from ~p:~w ~p\n\n", 
-%% 			       [ts2str(TimeStamp), ip(Addr), Port, Reason])
-%%             end;
-%%         false ->
-%%             ignore
-%%     end;
-%% format_msg({TimeStamp, Packet, {Addr, Port}}, Mib, Start, Stop) -> 
-%%     format_msg({TimeStamp, Packet, Addr, Port}, Mib, Start, Stop);
-%% format_msg({TimeStamp, Packet, Addr, Port}, Mib, Start, Stop) ->
-%%     case timestamp_filter(TimeStamp, Start, Stop) of
-%%         true ->
-%%             case (catch snmp_pdus:dec_message(binary_to_list(Packet))) of
-%%                 Msg when record(Msg, message) ->
-%%                     f(ts2str(TimeStamp), Msg, Addr, Port, Mib);
-%%                 {'EXIT', Reason} ->
-%%                     format_tab("** error in log file ~p\n\n", [Reason])
-%%             end;
-%%         false ->
-%%             ignore
-%%     end;
-%% format_msg(_, _Mib, _Start, _Stop) ->
-%%     format_tab("** unknown entry in log file\n\n", []).
-
 f(TimeStamp, SeqNo, 
   #message{version = Vsn, vsn_hdr = VsnHdr, data = Data}, 
   Addr, Port, Mib) ->
-    Str    = format_pdu(Data, Mib),
-    HdrStr = format_header(Vsn, VsnHdr),
-    case get_type(Data) of
-        trappdu ->
-            f_trap(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
-        'snmpv2-trap' ->
-            f_trap(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
-        'inform-request' ->
-            f_inform(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
-        'get-response' ->
-            f_response(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
-        report ->
-            f_report(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
-        _ ->
-            f_request(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port)
+    try
+	begin
+	    Str    = format_pdu(Data, Mib),
+	    HdrStr = format_header(Vsn, VsnHdr),
+	    case get_type(Data) of
+		trappdu ->
+		    f_trap(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
+		'snmpv2-trap' ->
+		    f_trap(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
+		'inform-request' ->
+		    f_inform(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
+		'get-response' ->
+		    f_response(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
+		report ->
+		    f_report(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port);
+		_ ->
+		    f_request(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port)
+	    end
+	end
+    catch
+	T:E ->
+	    ?vinfo("Failed formating log entry"
+		   "~n   TimeStamp:  ~p"
+		   "~n   SeqNo:      ~p"
+		   "~n   Data:       ~p"
+		   "~n   Vsn:        ~p"
+		   "~n   VsnHdr:     ~p"
+		   "~n   Addr:       ~p"
+		   "~n   Port:       ~p"
+		   "~n   Error Type: ~w"
+		   "~n   Error:      ~p", 
+		   [TimeStamp, SeqNo, Data, Vsn, VsnHdr, Addr, Port, T, E]),
+	    format_tab("** error while formating log entry ~p\n\n", [{T, E}])
     end.
 
 f_request(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port) ->
@@ -691,7 +821,7 @@ f_inform(TimeStamp, SeqNo, Vsn, HdrStr, Str, Addr, Port) ->
 %% Convert a timestamp 2-tupple to a printable string
 %%
 ts2str({Local,Universal}) ->
-    dat2str(Local) ++ " , " ++ dat2str(Universal);
+    lists:flatten(dat2str(Local) ++ " , " ++ dat2str(Universal));
 ts2str(_) ->
     "".
 
@@ -788,7 +918,7 @@ get_type(#pdu{type = Type}) ->
 
 
 ip({A,B,C,D}) ->
-    io_lib:format("~w.~w.~w.~w", [A,B,C,D]).
+    lists:flatten(io_lib:format("~w.~w.~w.~w", [A,B,C,D])).