Capturing the name of a running prg

[Bryan - Gendev]

My app consists of a large number of prg files. I would like to mantain a record of which prg is running at any one time and
record that in a log file.
I have the prg for a log file ('logging.prg') and would hope to add a call to it like
logging(myprogname) each time the subject prg is run.

So is there a way of saying myprogname = (program) at the top of each prg?

GenDev

 

[Chris Miller]

You can use PROGRAM() for that. or with the full path SYS(16). No need to reinvent the wheel.

So when you call the log function by

logging(Program())

the first passed in parameter will be the name of the PRG that called logging.

There's also a more detailed way to log what runs, line by line, which is SET COVERAGE TO somefile.log.
It creates very verbose logs, but sometimes they can be good to find out what exactly leads to errors, so that's nice for debugging purposes.

Chriss

 

[Mike Lewis]

I was also going to suggest passing the output of PROGRAM() to your logging function. But it has two problems:

1, You would have to insert the relevant line of code at the top of every one of your PRGs, which might be tedious and time-consuming.

2. It would cause the log to be written both in the development environment and in the distributed app, which might or might not be what you want.

If you have a large number of PRGs, you could perhaps write a simple program to automatically insert the relevant line at the top of each file. Use ADIR() to loop through the files; use FILETOSTR() and STRTOFILE() to read and write the contents into memory variables.

If you only want the log to be generated at development time, that is, not in the distributed app, use DEBUGOUT to send it to the Debug Output window from where it can be saved as a text file. The point is that DEBUGOUT is ignored when run from an EXE.

Mike

__________________________________
Mike Lewis (Edinburgh, Scotland)

Visual FoxPro articles, tips and downloads

 

[Chris Miller]

Use ADIR() to loop through the files; use FILETOSTR() and STRTOFILE() to read and write the contents into memory variables.

..and finally back to the files.

Both things have pros and cons

1. SET COVERAGE
a) pro: does not need any code changes than one line activating it and (optionally) one line deactivating it
b) pro: logs every line of code and is very detailed, including the time spent for each line of code executed, which is something you can't log with normal logging
c) con: logs every line of code and grows a large log file, which will need post processing as there's too much to just read through.
d) pro: You have a built in tool to process such coverage log files in Tools->Coverage Profiler (therefore the logs are not meant for human reading)

The last thing is also showing the reason it's called coverage logging. The intent is to find out whether a coverage testing of your code covers all code lines, i.e. your test cases go into each if and else branch or each case of a DOCASE...ENDCASE statement and the code coverage is thereful fully or not. It's not the only use of the log as another feature of the Coverage profile is computing the overall and average time spent on a line of code, too, so it's also for performance profiling.

2. DEBUGOUT or logging
a) con: you need to put in log calls into your code at every stage you'd like to see in your log file
b) pro: you can choose wherever and whatever to log, not only PROGRAM(), of course, you can log values of variables, you can also log timings as SECONDS() gives you a running up number of seconds since last midnight and there are more precise timestamps available with Windows API calls.
c) pro: you only log at points that interst you and get the concentrated log information you want.
d) pro: While you don't have a tool like Coverage Profiler the log files should tell you what you want to know without any postprocessing of the logged data.

In some cases 1 a) is a huge pro and in most cases the pros of 2b)-d) outweigh that. In your case, as you mainly want to know which programs run, coverage profiling is giving you that with one added line of code, though.

It works both in IDE and EXE. And Mike pointed out that DEBUGOUT only logs in the IDE while the debugger is open as an advantage. Well, often enough you actually want to know what was run by users, so when the EXE is used, that speaks for a logging.prg as you have it. On the other hand you can start or not start coverage logging checking _vfp.startmode, so you can also only log in the IDE in debug sessions and not in the EXE, if you want. I didn't mention that you can choose between logging to a text file or a dbf with your logging function - DEBUGOUT outputs into the debugout window of the debugger which can be saved to a text file. The text logs coverage generates are usable CSV, so you cna read them into a DBF, which means there's a balance of advantages/disadvantages about the file formats.

Chriss

 

[Chris Miller]

You neither need logging.prg, DEBUGOUT nor SET COVERAGE TO a file, if you're just interested to see what's executed. You can see that running code in the debugger, where it stops at each line, where you can look into variables and many more things while you single step through the code line by line. To some that may be the reason to not use the debugger as it's tedious to press F8 to advance line by line, but when you want to execute all say 1000 iterations of a loop without pressing F8 1000 times you have the feature to set the cursor in the code line after a loop in the trace window and pick the option "Run to cursor" (F7), to mention just one feature. You get other pros and cons that way, but it's obviously called debugger for a reason.

Chriss

 

[Mike Lewis]

OK, how about this for an idea ....

1. At the start of the app, execute [tt]SET COVERAGE TO MyLogFile.log[/tt]

2. Run the app.

3. Close the log file: [tt]SET COVERAGE TO[/tt].

4. You now have a large comma-delimited text file, named MyLogFiel.Log (or whatever you decided to call it in step 1 above). This has the following structure:

[COLOR=#204A87]Item Description
1    execution time
 
2    class executing the code
 
3    object, method, or procedure in which the code is found or called (this is the one
     you are interested in)
 
4    line number within the method or procedure
 
5    fully defined file
 
6    call stack level[/color]

5. Append that file into a cursor

6. Item 3 will contain the names of all the procedures that have been called. So now write a SQL command to get a list of unique names: [tt]SELECT DISTINCT ProcedureName FROM MyCursor INTO csrResults[/tt]

7. However, that third item will also contain the names of every method or function that is called. You only want the names of the PRGs. You can get rid of the methods by filtering out those entries where the second item is empty: [tt]SELECT DISTINCT ProcedureName FROM MyCursor WHERE EMPTY(ClassName) INTO csrResults[/tt]. Unfortunately, there doesn't appear to be a way of filtering out functions or procedures.

All this is very much off the top of my head. I haven't actually tried to do it. But I think it should give you what you want - or something reasonably close.

Mike


__________________________________
Mike Lewis (Edinburgh, Scotland)

Visual FoxPro articles, tips and downloads

 

[Chris Miller]

Good idea,

and if you now can't decide and wonder what we're using: I can, of course, only talk about myself, but there's always a mix of everything, that's useful. Logging has also other purposes than debugging, loggig is a whole topic in itself and there are even industry standard libraries to use like log4j in Java. The OS has the event log. So the tip about coverage logging is not at all meant as advice to not use your logging.prg.

If you say more about why you intend to log PROGRAM(), I'm sure we could recommend what to use to get what you need.

It always helps to have more background knowledge. Just for fun I just searched whether something like log4j exists in the VFP community, from Marco or atlopes, for example. Well, there is

https://spacefold.com/articles/log4fox/

from Lisa Slater Nicholls, not an unknown name, too.

Chriss

 

[Mike Lewis]

And just in case you are not completely put off by my suggestion, you could go one step further and automate the whole process. It would of course be easy to write a PRG to append the log file into a cursor and to run the SQL on it, as I described above. Better still, you could make it an add-in to the profiling app (see "Coverage Profiler Add-Ins" in the Help for info). Then the whole thing is almost reduced to a single command.

Mike

__________________________________
Mike Lewis (Edinburgh, Scotland)

Visual FoxPro articles, tips and downloads

 

[Bryan - Gendev]

Gentlemen,

Thank you so much for your detailed answers. I manually went through and added logging(program()) in each of my 50+ prgs.
This caused a problem as when some prg files were run the logging program code contained items not yet initialised.
However that is now solved and I am happy with the program name in my log files.
I'll have to think about the other options but pleased to know all that.

GenDev

 

[Chris Miller]

the logging program code contained items not yet initialised.

Well, that's clearly not working but you resolved it. I imagine the log file name was not yet set from the beginning. Your main prg should do that and, well, not have logging(program()) as its first line, obviously.

Chriss

 

[Chris Miller]

Just a slight warning about your methodology, doing this logging call at the start of each prg you can miss out where an EXE actually ended on with an error, because...

a) ...all programs put themselves into the log first, before the rest of them runs.
b) programs will usually branch off into other programs, i.e. DO other.prg or call other(parameters).
c) if a program called form some program returns, it's still the last prg in the log file.

So, when an error stops execution of the EXE at a point the running prg is not the last logged program(), but the last logged program() already returned, the log would point to the last perfectly fine running prg, not the one with the error.

This problem becomes no problem, if you additionally use the logging.prg in an error handler. Or, you also change any line after calling another prg like this:

* your existing code line
DO something.prg WITH parameters && or something(parameters)
* directly after returning from the other PRG add to the log
logging(program()) && once more

We don't know for which reason you actually log the execution of the prgs. If it's not for debugging purposes to know what kind of execution of prgs in a series leads up to an error, then only logging each program once at its start may very well be all you need. Since you already were busy changing 50 prgs you already lost the option to cover all that with just one SET COVERAGE TO logfile.log. Your log will be far less verbose and that may be fine, but keep in mind the last prg running may not be the last line of your log.

I actually assume your programs each have their functionality and you're using the log to see what you did on a day, then your simple logging is still fine for that use case.

Chriss

 

[TamarGranor]

I generally just put the whole call stack into my error log. It makes debugging so much easier. I have a routine called GetStack that looks like this:

[pre]
* Return the call stack as a string

LOCAL lnStackSize, laCallStack[1], lcStackInfo, lnStackLevel
store 0 to lnStackSize, laCallStack[1], lnStackLevel
store space(0) to lcStackInfo
* Use ASTACKINFO()
lnStackSize = ASTACKINFO(laCallStack)
for lnStackLevel = 1 TO m.lnStackSize
lcStackInfo = m.lcStackInfo + ;
" Level: " + TRANSFORM(laCallStack[m.lnStackLevel, 1]) + CHR(13) + CHR(10) + ;
" File: " + laCallStack[m.lnStackLevel, 2] + CHR(13) + CHR(10) + ;
" Module/Object: " + laCallStack[m.lnStackLevel, 3] + CHR(13) + CHR(10)
lcStackInfo = m.lcStackInfo + ;
" Line: " + TRANSFORM(laCallStack[m.lnStackLevel, 5]) + ;
": " + laCallStack[m.lnStackLevel, 6] + CHR(13) + CHR(10)
endfor lnStackLevel = 1 TO m.lnStackSize


RETURN m.lcStackInfo
[/pre]

I call this from the error handler and stick the info into a memo field in my error log table. But I also call this routine sometimes from DEBUGOUT, or from some other kind of logging.

Tamar

 

[Chris Miller]

Clearly astackinfo has more info than just the last program().

And sample of errorhandling in the VFP help suggest to call an error handler with parameters ERROR(), MESSAGE(), PROGRAM(), LINENO(), so just like calling logging(program()) the error handler receives PROGRAM() in one parameter. Indeed, you get all the informations except ERROR() and MESSAGE and more from ASTACKINFO and you also can get ERROR(), MESSAGE() from AERROR(), so an error handler doesn't necessarily need any parameter.

Aside from not knowing whether this logging(program()) calls are for debugging purposes, one one side you get less in a log like that than from ASTACKINGFO by only knowning which programs ran, but you don't just see the current stack with a log file that logs each call of programs.

A classic variable scoping error that also won't reveal itself with ASTACKINFO is that:

Dimension randomizedalphabets[10]
For i = 1 to 10
    Store getrandomizedalphabet() to randomizedalphabets[i]
Next i

Function getrandomizedalphabet
   alphabet = 'abcdefghijklmnopqrstuvwxyz'
   randomized = ''
   =Rand(-1)
   For i = 1 to 26
       letter = Substr(alphabet,Rand()*Len(alphabet)+1,1)
       alphabet = Chrtran(alphabet,letter,'')
       randomized = randomized +letter
   EndFor
   Return randomized

Imagine you have getrandomizedalphabet in a separate prg then you'd only see one call to getrandomizedalphabet from the program calling it, not 10, and you'd become suspiscious why already after the return from the first getrandomizedalphabet call you get an error 'subscript is outside of defined range', so you'd investigate why i would be >10 in the first iteration of the For i = 1 to 10 loop.

So having what gendev now already created and combining that with a simple error handler, which only also logs the last Program(), you'd already have a list of programs that ran that's more telling, despite not telling in which line numbers calls to other programs or functions were made, you could add further logging calls for that.

gendevs idea is not the worst approach, and we already discussed the disadvantage of coverage being very verbose and less flexible with what is logged into the coverage log. All in all it's not a bad idea to have a program flow log that's between what ASTACKINFO gives you as a snapshot of the stack vs the extreme detailed coverage profiling log.

Chriss

 

[Bryan - Gendev]

I have not been able to get to the problem I am chasing just using program() to my log file.
I therefore thought I would try SET COVERAGE TO.
I did this and set to run main.prg in the debugger.
This has stopped the debugger at a point in the early code of main.prg with a red dot on the far left of a line in the prg.
I have seen this once before but don't know what it means or how to get rid of it.
Anyone help?

GenDev

 

[Bryan - Gendev]

Ha! Fixed! Just a clumsy click!

Gendev

 

[Chris Miller]

Well, that red dot is a break point you set in a program to halt at that point and start the debugger. It has done its job.

It's also the usual way to chase a problem you know occurs by starting at a point you know is close to when the problem occurs. For example, if you know a click on a button always causes the problem you chae, then setting a break point in the click event is a good idea to find out what exactly happens step by step.

Chriss

 

[Bryan - Gendev]

Setting COVERAGE ON to a file has enabled me to solve my problem - thanks all
CtrlF inside the coverage file has enabled me to find the occurrences I needed.

I also find a number of on error lines with a number.
How do I decode these numbers?
for example 0.000021,,on error,,,9

Thanks
GenDev

 

[Chris Miller]

The line logged previous to the on error line is the one that errors. ON ERROR itself has no location or line number, it is running, because an error causes it.

So you see a lot of consecutive commas, as there are a lot of things without value. Mike Lewis has posted at which position/column the values have which meaning. So, for example, the 9 at the end is the stack level. Something called something else, which called something else, etc. and the number of calls, the depth of calls you're currently in is the stack level. 9 is quite high, might be a recursion, maybe an unintentional recursion that, when gone deep enough causes an error.

Chriss

 

[Mike Lewis]

0.000021,,on error,,,9

The first number is the time it takes the line of code to execute. The last number is the stack level. Neither of these will be relevant for your particular problem.

There's more information in the Help topic, "Coverage Profiler Log File".

Mike

__________________________________
Mike Lewis (Edinburgh, Scotland)

Visual FoxPro articles, tips and downloads

 

[Chris Miller]

has enabled me to solve my problem

Congratulations on that.

There are a lot of things said in this thread, which you obviously overlooked. One thing is that while the coverage log is very useful, it does not provide as simple info as what error number and error message was caused. The logged "on error" is just stating that the previous line caused the error event that triggers whetever is defined with ON ERROR, if you'd introduce an error handler you could get the additional information about the error that often enough helps and in many cases is even sufficient to see what's gone wrong, if you combine it with writing out the state of important variables etc.

Neither logging(program()) nor set coverage to logfile will replace error handling, as you do this for finding the cause of an error, there's a lot already said what you can do on top or instead of logging, too.

Chriss