Improve documentation for asynTrace

[MarkRivers]

From an e-mail exchange between Mark Rivers and Ben Franksen.

Hi Mark

ah, thanks, I didn't know that (nor is it obvious, at least not by
looking at the docs or the header file).

BTW, it would help a lot if this and also the possible constants to use
for asynSetTraceMask and asynSetTraceIOMask would be listed together
with these functions in the asynDriver docs.

Cheers
Ben

On 11/20/2017 05:17 PM, Mark Rivers wrote:
> Hi Ben,
> 
> "reason" is the asyn traceMask bit mask.  The bits are:
> 
> /* traceMask definitions*/
> #define ASYN_TRACE_ERROR     0x0001
> #define ASYN_TRACEIO_DEVICE  0x0002
> #define ASYN_TRACEIO_FILTER  0x0004
> #define ASYN_TRACEIO_DRIVER  0x0008
> #define ASYN_TRACE_FLOW      0x0010
> #define ASYN_TRACE_WARNING   0x0020
> 
> I suggest calling asynPrint as follows:
> ASYN_TRACE_ERROR for errors
> ASYN_TRACE_WARNING for warnings
> ASYN_TRACE_FLOW for debugging of flow.
> 
> Since streamDevice is device support I suggest calling asynPrintIO in this case:
> ASYN_TRACEIO_DEVICE for debugging output that contains data
> 
> Mark
> 
> -----Original Message-----
> From: Benjamin Franksen [mailto:benjamin.franksen@helmholtz-berlin.de] 
> Sent: Monday, November 20, 2017 9:48 AM
> To: Mark Rivers
> Subject: Re: How to turn off spewing messaging from asyn/stream devicse.
> 
> Hi Mark
> 
> On 11/09/2017 11:34 PM, Mark Rivers wrote:
>> However, because those messages are coming from streamDevice and not
>> asyn that does not work.  I have asked Dirk to consider changing the
>> streamDevice error reporting so that if asyn is being used (which it
>> almost always is) then it uses the asynTrace mechanism for control
>> messages.  That would allow controlling them as above.
> 
> I plan to make this change in StreamDevice. The fact that the asyn
> backend is confined to a single module actually makes things easier. I
> am planning to change only those calls to the 'error' that result from
> asyn calls indicating failure, since these are the ones that we want to
> filter.
> 
> The problem I have is this: using asynTrace requires to provide the
> print method with an 'int reason' argument. I don't know what is
> expected here. How do I get hold of a suitable 'reason'?
> 
> Cheers
> Ben

The asynDriver.html documentation needs to be improved to explain this better.

[tboegi]

Please allow a comment:
For the motor drivers I needed another traceMask bit:

• Whenever a new set point is send to the driver to move the motor
• Whenever the motor runs into a limit switch, status is changed from moving to stop...
  In other words, when things happen and PV's are updated, or when PV's are updated
  and things happen.

I added the #define ASYN_TRACE_INFO 0x0040. (There is even an old pull request)
Is there a better suggestion ?

[MarkRivers]

I'm open to the suggestion of a new ASYN_TRACE_INFO flag. If you look at the old pull request #9 you'll see that Ulrik pointed out that there is more work to be done. The asynRecord needs to be updated to support it, including the medm screen. asynDriver.html also needs to be updated.

For limit switch would ASYN_TRACE_WARNING be more appropriate. How do you propose to describe when to use ASYN_TRACE_FLOW, ASYN_TRACE_WARNING, and ASYN_TRACEIO_DRIVER vs ASYN_TRACE_INFO?

[tboegi]

Right. I will come back with more input the next days.

[tboegi]

Some work in progress, not completed.
Where should the documentation go in the end?
The html file ?

/* traceMask definitions*/
#define ASYN_TRACE_ERROR 0x0001
#define ASYN_TRACEIO_DEVICE 0x0002
#define ASYN_TRACEIO_FILTER 0x0004
#define ASYN_TRACEIO_DRIVER 0x0008
#define ASYN_TRACE_FLOW 0x0010
#define ASYN_TRACE_WARNING 0x0020

ASYN_TRACE_ERROR:
Serious error, trace thongs that should never happen.

ASYN_TRACEIO_DEVICE:
How much data is send to or received from the device.
(In case reading or writing fails, ASYN_TRACE_ERROR
is used instead)

ASYN_TRACEIO_FILTER:
Used by the interpose filter

ASYN_TRACEIO_DRIVER:
How much data is send/received in
e.g. asynPortDriver, drvAsynIPPort, etc

ASYN_TRACE_FLOW:
The "flow of control and data function calls
E.g. open/close/read/write/lock/queue

ASYN_TRACE_WARNING:
"This is intended to be used for messages that are less serious than ASYN_TRACE_ERROR,
but more serious than ASYN_TRACE_FLOW"
E.g. Buffer overflow,
multiple interrupt callbacks between processing

One personal note:

1. The border between ERROR and WARNING is not easy to draw,
   this one may be a warning:
   asynPrint(pasynUser,ASYN_TRACE_ERROR,
   "%s %d autoConnect connectDevice failed.\n",

2. ERROR and WARNING should be occur never in the logs.
   All other messages are quite "spammy" if turned on, since
   they log each and every poll.
   I am missing a trace level which is between WARNING and FLOW
   which traces e.g. state changes (motor is commanded to start or
   motor has stopped)
   All the (state) transitions which are a result of a PV change
   (VAL field) or are resulting in a change of a state field
   (e.g. MOVN, DMOV)
   The suggestion is to add INFO for this, I just need to update
   the PR.

[MarkRivers]

Yes, the documentation should go in asynDriver.html. Note that this file already has documentation on the intended use of ASYN_TRACE_ERROR, etc. in the section titled "Trace Interface". Thus I don't really understand Ben's comment

BTW, it would help a lot if this and also the possible constants to use
for asynSetTraceMask and asynSetTraceIOMask would be listed together
with these functions in the asynDriver docs.

because the constants and functions are described together in the docs. Ben, how would you improve the documentation there?

---

asynTrace

asynDriver provides a trace facility with the following attributes:

• Tracing is turned on/off for individual devices, i.e. a portName, addr.
• Trace has a global trace mask for asynUsers not connected to a port or port, addr.
• The output is sent to a file or to stdout or to errlog.
• A mask determines the type of information that can be displayed. The various choices can be ORed together. The default value of this mask when a port is created is ASYN_TRACE_ERROR.
  • ASYN_TRACE_ERROR Run time errors are reported, e.g. timeouts.
  • ASYN_TRACEIO_DEVICE Device support reports I/O activity.
  • ASYN_TRACEIO_FILTER Any layer between device support and the low level driver reports any filtering it does on I/O.
  • ASYN_TRACEIO_DRIVER Low level driver reports I/O activity.
  • ASYN_TRACE_FLOW Report logic flow. Device support should report all queue requests, callbacks entered, and all calls to drivers. Layers between device support and low level drivers should report all calls they make to lower level drivers. Low level drivers report calls they make to other support.
  • ASYN_TRACE_WARNING Report warnings, i.e. conditions that are between ASYN_TRACE_ERROR and ASYN_TRACE_FLOW.
• Another mask determines how message buffers are printed. The various choices can be ORed together. The default value of this mask when a port is created is ASYN_TRACEIO_NODATA.
  • ASYN_TRACEIO_NODATA Don't print any data from the message buffers.
  • ASYN_TRACEIO_ASCII Print with a "%s" style format.
  • ASYN_TRACEIO_ESCAPE Call epicsStrPrintEscaped.
  • ASYN_TRACEIO_HEX Print each byte with " %2.2x".
• Another mask determines what information is printed at the beginning of each message. The various choices can be ORed together. The default value of this mask when a port is created is
  • ASYN_TRACEINFO_TIME.
  • ASYN_TRACEINFO_TIME prints the date and time of the message.
  • ASYN_TRACEINFO_PORT prints [port,addr,reason], where port is the port name, addr is the asyn address, and reason is pasynUser->reason. These are the 3 pieces of "addressing" information in asyn.
  • ASYN_TRACEINFO_SOURCE prints the file name and line number, i.e. [FILE,LINE] where the asynPrint or asynPrintIO statement occurs.
  • ASYN_TRACEINFO_THREAD prints the thread name, thread ID and thread priority, i.e. [epicsThreadGetNameSelf(), epicsThreadGetIdSelf(), epicsThreadGetPrioritySelf()].

---

[bfrk]

I see. Well, I searched for "asynSetTrace" and found (only) the list of iocsh commands under Diagnostic Aids. It did not occur to me to look elsewhere for documentation of the constants. Perhaps a link from the above mentioned section to the asynTrace chapter would make it easier for newcomers to find the constants and their meaning.

[bfrk]

Also, from a user perspective, it would be useful to include the numeric values in the docs, since the constants cannot be used when invoking asynSetTrace[IO]Mask from the (IOC) shell.

[MarkRivers]

I have made a number of improvements to the document:

• All level 3 headers are now in the table of contents. Thus you can now directly see and click to the Trace Interface section when viewing the table of contents.
• Added links in the setTraceMask, setTraceIOMask etc. descriptions to the location of the definitions of the trace mask bits. These include the numeric values, as they always have.
• Added documentation for more of the test applications. Moved this to the end of the document. More still need to be added.
• Used CSS styles to define layout of h2 and h3, rather than repetitive code.

You can preview the document here:
http://cars.uchicago.edu/software/epics/asynDriver.html

[tboegi]

Thanks Mark.
I have 2 comments:

1. Does it make sense to mention the iocsh commands to set the traces,
   at the place where the trace bits are defined ?
   (Search for "#define ASYN_TRACEIO_FILTER 0x0004"
   /* traceMask definitions*/
   #define ASYN_TRACE_ERROR 0x0001
   #define ASYN_TRACEIO_DEVICE 0x0002
   #define ASYN_TRACEIO_FILTER 0x0004
   #define ASYN_TRACEIO_DRIVER 0x0008
   #define ASYN_TRACE_FLOW 0x0010
   #define ASYN_TRACE_WARNING 0x0020
   The bits may be or-ed together and used in the iocsh command:
   asynSetTraceMask(portName,addr,mask)

/* traceIO mask definitions*/
#define ASYN_TRACEIO_NODATA 0x0000
#define ASYN_TRACEIO_ASCII 0x0001
#define ASYN_TRACEIO_ESCAPE 0x0002
#define ASYN_TRACEIO_HEX 0x0004
The bits may be or-ed together and used in the iocsh command:
asynSetTraceIOMask(portName,addr,iomask)

(And the same for the info mask)

asynSetTraceIOMask("$(ASYN_PORT)", -1, 2)
asynSetTraceIOMask(portName,addr,mask)

[tboegi]

And the other comment:
While we and you are at it, does it make sense to define a user bit ?
Did you have the chance to look at a possible improvement :
#63

[bfrk]

Thanks Mark, very nice! As far as I am concerned this is exactly the sort of improvement I wished for.

[MarkRivers]

These improvements are completed.