1. Logging tools

Forked from Re: Coding practice for better user-proofing

petelomax said...

Another trick I've started using recently is along the lines of logMsg("pemit2.e line 1443, ...").
Obviously the 1443 gets out-of-date pretty quickly, but you can easily search for it, in the right file.
Helps me out a lot on big complex apps when messages start appearing weeks or months after I added them.
The examples given are fine for debugging a single routine, but not really the whole process.

Pete

irv said...

Some programming languages (I forget which ones at the moment) have a way to include the current line number in an error message. So your error lines could read printf(1,"Error in line ..."), using some variable containing the current line #. I wonder if such a capability could be added to Eu?

Hm... the thought occurs to me that crash() already has that information. Maybe that would be a starting point for writing such a routine.

Euphoria 4.1 includes some new debugging tools, which includes a call_stack() function for some basic code introspection.

I've written some additional logging tools to provide some more modular logging. Perhaps it can be included in the 4.1 release.

This code will also work with 4.0, but for obvious reasons the call stack macros will not be parsed.

Code is here, complete with documentation: Logging tools

-- demo.ex 
 
include std/console.e 
include std/logging.e 
include std/io.e 
 
procedure main() 
     
    integer test_log = open( "demo.log", "w" ) 
     
    set_log_header( "%s %s %s %s:%s %s() - ", 
        {__DATE__,__TIME__,__LEVEL__, 
        __FILE__,__LINE__,__ROUTINE__} ) 
    set_log_output({ STDOUT, test_log }) 
    set_log_level( LOG_VERBOSE ) 
     
    write_log( LOG_SILENT, "zero" ) 
    write_log( LOG_SEVERE, "one" ) 
    write_log( LOG_ERRORS, "two" ) 
    write_log( LOG_WARNING, "three" ) 
    write_log( LOG_VERBOSE, "four" ) 
     
    close( test_log ) 
     
    maybe_any_key() 
     
end procedure 
 
main() 

> eui demo.ex 
2015/05/13 13:31:15 LOG_SILENT demo.ex:17 main() - zero 
2015/05/13 13:31:15 LOG_SEVERE demo.ex:18 main() - one 
2015/05/13 13:31:15 LOG_ERRORS demo.ex:19 main() - two 
2015/05/13 13:31:15 LOG_WARNING demo.ex:20 main() - three 
2015/05/13 13:31:15 LOG_VERBOSE demo.ex:22 main() - four 

-Greg

new topic     » topic index » view message » categorize

2. Re: Logging tools

@Developers,
Is there some way to bring some Euphoria internal parser / trace variables in as readable by the user Euphoria code?
For example, the name of the current procedure/function we are in, maybe a sequence containing the call stack, and the source line number. Note, I am asking about READ only please, I do not want to open the can of worms by asking for:
a) The line number to be the target of a goto
b) The line number to be updateable by the user, thereby potentially enabling a variable goto
c) Ditto no proc/func calls allowed to whatever is in the call stack
This would simplify this somewhat ugly and repetitive code I am doing at the moment:

------------------------------------------------------------------- 
function shared_vm_usage(sequence servername) -- v530  
sequence s1, s2 
integer i1, i2 
s1 = {} 
s1 = append(s1,"shared_vm_usage") 
s1 = append(s1,debug_level) 
s1 = append(s1,03751) 
s2 = {} 
s2 = append(s2,servername) 
s1 = append(s1,s2) 
program_debug(s1)  
i2 = 0 
s1 = get_hardware_serial(servername)  
i1 = find_from(s1,vm_server_serials,1)  
if i1 > 0 then  
	i2 = vm_server_inuse[i1] 
end if	   
return i2 
end function 
--------------------------------------------------------------------- 
----------------------------------------------------------------------------------------------------- 
-- standard debug procedure 
procedure program_debug(sequence passed_sequence) 
   sequence caller_name, caller_vars, s1, s2, s3, s4  
   integer caller_debug_level, caller_line_nr, i1, i2, i3, i4 
   object o1 
   i1 = 0 
   i2 = 0 
   caller_name = passed_sequence[1] 
   caller_debug_level = passed_sequence[2] 
   caller_line_nr = passed_sequence[3]  
   caller_vars = passed_sequence[4] 
   -- store the call counts per routine if debug > 2 
   if caller_debug_level > 2 then -- only if debug is not 0 
     i1 = find_from(caller_name,procmap,1) 
     if i1 = 0 then 
       procmap = append(procmap,caller_name) 
       procmap_line = append(procmap_line,caller_line_nr) 
       procmap_count = append(procmap_count,1) 
       i1 = i1 + 1 
      else 
       procmap_count[i1] = procmap_count[i1] + 1 
     end if 
    -- show the calling results of named procs 
     if find_from(caller_name,dump_proccount,1) !=0 then  
  	   i2 = 0 
  	   while i2 < length(procmap) do  
  		    i2 = i2 + 1 
  		    s1 = procmap[i2] 
  		    if compare(caller_name,s1) = 0 then 
  		       s2 = sprintf("%g",{procmap_count[i2]})  
  		       s4 = sprintf("%g",{procmap_line[i2]}) 
  		       writelog("Debug 3 Routine " & s1 & " at line " & s4 & " has count "& s2) 
  		    end if    
  	   end while 
     end if		 
   end if  
   -- turn on trace for specified procedure/function in config 
   if caller_debug_level > 3 then  
     if find_from(caller_name,trace_names,1) != 0 then 
       trace(1) 
      else  
   	   trace(0)  
     end if 
   end if 
   -- 
   if i2 > 0 then  
     s4 = sprintf("%g",{procmap_line[i2]})  
   end if 
   if i1 > 0 then  
     s4 = sprintf("%g",{procmap_line[i1]})  
   end if      
   if caller_debug_level = 3 then   -- don't do this for level 4 as well 
    	if find_from(caller_name,hidetrace,1) = 0 then -- v512 supress certain known calls 
        writelog("Debug 3 Routine '" & caller_name & "' called at line " & s4) 
    else  
        if procmap_count[i1] = 1 then -- always show the first time its called 
    	     writelog("Debug 3 Routine '" & caller_name & "' called at line " & s4) 
        end if	  	  
      end if    
   end if 
   if caller_debug_level > 3 then 
	   i4 = 0 
	   i3 = 0 
	   s1 = {} 
	   while i4 < length(caller_vars) do 
	     i4 = i4 + 1 
	     o1 = caller_vars[i4] 
	     if sequence(o1) then  
	  	   s2 = o1 
	  	   s1 = s1 & s2 & " " 
	  	   i3 = 1 
	     end if 
	     if integer(o1) then  
	  	   i2 = o1 
	  	   s3 = sprintf("%g",{i2})  
	  	   s1 = s1 & s3 & " " 
	  	   i3 = 1 
	     end if 
	     if atom(o1) then 	 
	       i2 = o1 
	  	   s3 = sprintf("%g",{i2}) 
	  	   s1 = s1 & s3 & " " 
	  	   i3 = 1 
	     end if 
	     if i3 = 0 then -- assume object if not atom/int/seq 
	  	   s2 = o1 
	  	   s1 = s1 & s2 & " " 
	  	   i3 = 1 
	     end if 
	   end while 
	   if find_from(caller_name,hidetrace,1) = 0 then -- v512 supress certain known calls 
	      writelog("Debug 4 Routine '" & caller_name & "' called at line " & s4 & ", passing vars " & s1) 
	    else  
        if procmap_count[i1] = 1 then -- always show the first time its called 
    	     writelog("Debug 4 Routine '" & caller_name & "' called at line " & s4 & ", passing vars " & s1) 
        end if	 
	   end if   
   end if 
end procedure          
------------------------------------------------------------------- 

Where program_debug is being passed the name, line number, variables etc

new topic     » goto parent     » topic index » view message » categorize

3. Re: Logging tools

fizzpopsoft said...

@Developers,
Is there some way to bring some Euphoria internal parser / trace variables in as readable by the user Euphoria code?
For example, the name of the current procedure/function we are in, maybe a sequence containing the call stack, and the source line number.

Uhm, the answer to this is in the first post of this thread.

fizzpopsoft said...

This would simplify this somewhat ugly and repetitive code I am doing at the moment:

------------------------------------------------------------------- 
function shared_vm_usage(sequence servername) -- v530  
sequence s1, s2 
integer i1, i2 
s1 = {} 
s1 = append(s1,"shared_vm_usage") 
s1 = append(s1,debug_level) 
s1 = append(s1,03751) 
s2 = {} 
s2 = append(s2,servername) 
s1 = append(s1,s2) 
program_debug(s1)  
i2 = 0 
s1 = get_hardware_serial(servername)  
i1 = find_from(s1,vm_server_serials,1)  
if i1 > 0 then  
	i2 = vm_server_inuse[i1] 
end if	   
return i2 
end function 
--------------------------------------------------------------------- 
----------------------------------------------------------------------------------------------------- 
-- standard debug procedure 
procedure program_debug(sequence passed_sequence) 
   sequence caller_name, caller_vars, s1, s2, s3, s4  
   integer caller_debug_level, caller_line_nr, i1, i2, i3, i4 
   object o1 
   i1 = 0 
   i2 = 0 
   caller_name = passed_sequence[1] 
   caller_debug_level = passed_sequence[2] 
   caller_line_nr = passed_sequence[3]  
   caller_vars = passed_sequence[4] 
   -- store the call counts per routine if debug > 2 
   if caller_debug_level > 2 then -- only if debug is not 0 
     i1 = find_from(caller_name,procmap,1) 
     if i1 = 0 then 
       procmap = append(procmap,caller_name) 
       procmap_line = append(procmap_line,caller_line_nr) 
       procmap_count = append(procmap_count,1) 
       i1 = i1 + 1 
      else 
       procmap_count[i1] = procmap_count[i1] + 1 
     end if 
    -- show the calling results of named procs 
     if find_from(caller_name,dump_proccount,1) !=0 then  
  	   i2 = 0 
  	   while i2 < length(procmap) do  
  		    i2 = i2 + 1 
  		    s1 = procmap[i2] 
  		    if compare(caller_name,s1) = 0 then 
  		       s2 = sprintf("%g",{procmap_count[i2]})  
  		       s4 = sprintf("%g",{procmap_line[i2]}) 
  		       writelog("Debug 3 Routine " & s1 & " at line " & s4 & " has count "& s2) 
  		    end if    
  	   end while 
     end if		 
   end if  
   -- turn on trace for specified procedure/function in config 
   if caller_debug_level > 3 then  
     if find_from(caller_name,trace_names,1) != 0 then 
       trace(1) 
      else  
   	   trace(0)  
     end if 
   end if 
   -- 
   if i2 > 0 then  
     s4 = sprintf("%g",{procmap_line[i2]})  
   end if 
   if i1 > 0 then  
     s4 = sprintf("%g",{procmap_line[i1]})  
   end if      
   if caller_debug_level = 3 then   -- don't do this for level 4 as well 
    	if find_from(caller_name,hidetrace,1) = 0 then -- v512 supress certain known calls 
        writelog("Debug 3 Routine '" & caller_name & "' called at line " & s4) 
    else  
        if procmap_count[i1] = 1 then -- always show the first time its called 
    	     writelog("Debug 3 Routine '" & caller_name & "' called at line " & s4) 
        end if	  	  
      end if    
   end if 
   if caller_debug_level > 3 then 
	   i4 = 0 
	   i3 = 0 
	   s1 = {} 
	   while i4 < length(caller_vars) do 
	     i4 = i4 + 1 
	     o1 = caller_vars[i4] 
	     if sequence(o1) then  
	  	   s2 = o1 
	  	   s1 = s1 & s2 & " " 
	  	   i3 = 1 
	     end if 
	     if integer(o1) then  
	  	   i2 = o1 
	  	   s3 = sprintf("%g",{i2})  
	  	   s1 = s1 & s3 & " " 
	  	   i3 = 1 
	     end if 
	     if atom(o1) then 	 
	       i2 = o1 
	  	   s3 = sprintf("%g",{i2}) 
	  	   s1 = s1 & s3 & " " 
	  	   i3 = 1 
	     end if 
	     if i3 = 0 then -- assume object if not atom/int/seq 
	  	   s2 = o1 
	  	   s1 = s1 & s2 & " " 
	  	   i3 = 1 
	     end if 
	   end while 
	   if find_from(caller_name,hidetrace,1) = 0 then -- v512 supress certain known calls 
	      writelog("Debug 4 Routine '" & caller_name & "' called at line " & s4 & ", passing vars " & s1) 
	    else  
        if procmap_count[i1] = 1 then -- always show the first time its called 
    	     writelog("Debug 4 Routine '" & caller_name & "' called at line " & s4 & ", passing vars " & s1) 
        end if	 
	   end if   
   end if 
end procedure          
------------------------------------------------------------------- 

Where program_debug is being passed the name, line number, variables etc

Most of that (other than caller_vars) can be obtained from passing call_stack() in. To get the variables would probably require something tricky like hooking display_var() and using symbol_lookup() and/or get_symbol_table() (all in include/euphoria/debug/debug.e).

new topic     » goto parent     » topic index » view message » categorize

4. Re: Logging tools

OK thanks Greg Jim,
The online manual has no hits for call_stack() so I will search the forum. I honestly didn't see the single line where the magic call_stack was called earlier, my bad.
A gotcha for me is I am using Eu v4.05 due to translator issues with both GCC and Watcom, and call_stack() is Euphoria v4.1 only according to the ifdef's . Ah well, suppose I had better give v4.1 another go... but will have to go back again if the translator does not work.
I'll do a backup, reboot, clean install v4.1, reboot and see.
Regards,
Alan

new topic     » goto parent     » topic index » view message » categorize

Search



Quick Links

User menu

Not signed in.

Misc Menu