add some per-record debugging

GNUmakefile

@@ -24,11 +24,11 @@ HEADERS += src/StreamFormat.h
 HEADERS += src/StreamFormatConverter.h
 HEADERS += src/StreamBuffer.h
 HEADERS += src/StreamError.h
-HEADERS += src/StreamVersion.h
 HEADERS += src/StreamProtocol.h
 HEADERS += src/StreamBusInterface.h
 HEADERS += src/StreamCore.h
 HEADERS += src/MacroMagic.h
+HEADERS += $(COMMON_DIR)/StreamVersion.h
 
 CPPFLAGS += -DSTREAM_INTERNAL -I$(COMMON_DIR)
 

docs/setup.html

@@ -385,35 +385,45 @@ See the <a href="protocol.html">next chapter</a> for protocol files in depth.
 Generation of debug and error messages is controlled with two shell variables,
 <code>streamDebug</code> and <code>streamError</code>.
 Setting those variables to 1 (actually to any number but 0) enables the
-messages.
+messages. A few noisy and rarely useful debug messages are only enabled when
+setting <code>streamDebug</code> to 2.
 Per default debug messages are switched off and error messages are switched on.
 Errors occuring while loading protocol files are always shown.
 </p>
 <p>
-Warning: Enabling debug messages can create a lot of output!
+Warning: Enabling debug messages this way can create a lot of output!
-At the moment, there is no way to set filters on debug or error messages.
+Therefore, some limited debugging can be enabled per record, independent of
+the <code>streamDebug</code> variable using the <code>.TPRO</code> field of
+the record. Currently, setting <code>.TPRO</code> to 1 or 2 enables some
+basic information about the processing of a record and its i/o.
 </p>
 <p>
 Debug output can be redirected to a file with the command
 <code>streamSetLogfile("<var>filename</var>")</code>.
-When called without a filename, debug output is directed back
+If the file already exists, it will be overwritten, not appended to.
-to the console.
+While debug messages are only written to the defined log file, error messages
+are still printed to <var>stderr</var> too.
+Calling <code>streamSetLogfile</code> without a filename directs debug output
+back to <var>stderr</var> and closes the log file.
 </p>
 <p>
-By default the debug/error output is set to be colored if the terminal allows
+By default, error messages to the console are printed in red color if
-it but this can be set to always colored or never colored by setting 
+<var>stderr</var> is a tty at startup time, using ANSI color codes. Some
-<code>streamDebugColored</code> to 1 or 0 respectively.
+terminals may not support this properly.
+The variable <code>streamDebugColored</code> can be set to 0 or 1 to
+disable or enable colored error messages explicitly.
+Error messages written to a log file do not use colors.
 </p>
 <p>
 Error and debug messages are prefixed with a time stamp unless the variable
 <code>streamMsgTimeStamped</code> is set to 0.
 </p>
 <p>
-When a device is disconnected StreamDevice can produce many repeated timeout 
+when a device is unresponsive, StreamDevice may produce many repeated timeout 
-messages. To reduce this logging you can set <code>streamErrorDeadTime</code>
+messages. To reduce this, you can set <code>streamErrorDeadTime</code>
-to an integer number of seconds. When this is set repeated timeout messages 
+to an integer number of seconds. In this case, repeated timeout messages 
-will not be printed in the specified dead time after the last message. The 
+will not be printed during the specified dead time after the last printed
-default dead time is 0, resulting in every message being printed.
+message. The default dead time is 0, resulting in every message being printed.
 </p>
 
 <h3>Example (vxWorks):</h3>

src/StreamBuffer.cc

@@ -102,7 +102,7 @@ init(const void* s, ssize_t minsize)
 }
 
 // How the buffer looks like:
-// |----free-----|####used####|--------00--------|
+// |----junk-----|####used####|--------00--------|
 ///|<--- offs -->|<-- len --->|<- cap-offs-len ->|
 // 0            offs      offs+len              cap
 //               |<-------------- minsize --------------->
@@ -254,39 +254,71 @@ replace(ssize_t remstart, ssize_t remlen, const void* ins, ssize_t inslen)
     if (inslen < 0) inslen = 0;
     size_t remend = remstart+remlen;
     size_t newlen = len+inslen-remlen;
+
+// How the buffer looks like before and after:
+// |---junk---|##content_start##|/////////remove_this////////|##content_end##|0000|
+// |<- offs ->|<-- remstart --->|<--------- remlen --------->|               |    |
+// |          |<--------------------- len ---------------------------------->|    |
+// 0         offs           offs+remstart                offs+remend    offs+len cap
+//
+// If content size stays the same, no need to move old content:
+// |---junk---|##content_start##|+++++++inserted_text++++++++|##content_end##|0000|
+//                              |<----- inslen==remlen ----->|         newlen==len
+//
+// If content shrinks (need to clear end of buffer):          |< clear this >|
+// |---junk---|##content_start##|inserted_text|##content_end##|00000000000000|0000|
+// 0         offs               |<- inslen -->|               |< len-newlen >|
+//                                                        offs+newlen    offs+len
+//
+// If content grows but still fits (make sure to keep at least one 0 byte at end):
+// |---junk---|##content_start##|++++++++inserted_text++++++++++|##content_end##|0|
+// |<- offs ->|<--------------------- newlen ---------------------------------->| |
+// 0         offs                                                           offs+newlen<cap
+//
+// If content would overflow, moving to offs 0 may help:
+// May need to clear end if newlen < offs+len:                       |<clear>|
+// |##content_start##|++++++++inserted_text++++++++++|##content_end##|0000000|0000|
+// |<--------------------- newlen ---------------------------------->|       |
+//                                                                newlen  offs+len
+// 
+// Otherwise we need to copy to a new buffer.
+
+
     if (cap <= newlen)
     {
-        // buffer too short
+        // buffer too short, copy to new buffer
         size_t newcap;
         for (newcap = sizeof(local)*2; newcap <= newlen; newcap *= 2);
         char* newbuffer = new char[newcap];
-        memcpy(newbuffer, buffer+offs, remstart);
+        memcpy(newbuffer, buffer+offs, remstart);                           // copy content start
-        memcpy(newbuffer+remstart, ins, inslen);
+        memcpy(newbuffer+remstart, ins, inslen);                            // insert
-        memcpy(newbuffer+remstart+inslen, buffer+offs+remend, len-remend);
+        memcpy(newbuffer+remstart+inslen, buffer+offs+remend, len-remend);  // copy content end
-        memset(newbuffer+newlen, 0, newcap-newlen);
+        memset(newbuffer+newlen, 0, newcap-newlen);                         // clear buffer end
         if (buffer != local)
-        {
+            delete[] buffer;
-            delete [] buffer;
-        }
         buffer = newbuffer;
         cap = newcap;
         offs = 0;
     }
     else
     {
-        if (newlen+offs<=cap)
+        if (offs+newlen < cap)
         {
-            // move to start of buffer
+            // modified content still fits with current offs, just move content end
-            memmove(buffer+offs+remstart+inslen, buffer+offs+remend, len-remend);
+            if (newlen != len)
-            memcpy(buffer+offs+remstart, ins, inslen);
+                memmove(buffer+offs+remstart+inslen, buffer+offs+remend, len-remend); // move old content end if necessary
-            if (newlen<len) memset(buffer+offs+newlen, 0, len-newlen);
+            memcpy(buffer+offs+remstart, ins, inslen);                                // insert before
+            if (newlen < len)
+                memset(buffer+offs+newlen, 0, len-newlen);                            // clear buffer end if content shrunk
         }
         else
         {
-            memmove(buffer,buffer+offs,remstart);
+            // move content to start of buffer
-            memmove(buffer+remstart+inslen, buffer+offs+remend, len-remend);
+            memmove(buffer, buffer+offs, remstart);                                   // move content start to 0 offs
-            memcpy(buffer+remstart, ins, inslen);
+            memmove(buffer+remstart+inslen, buffer+offs+remend, len-remend);          // move content end
-            if (newlen<len) memset(buffer+newlen, 0, len-newlen);
+            memcpy(buffer+remstart, ins, inslen);                                     // insert in between
+            if (newlen < offs+len)
+                memset(buffer+newlen, 0, offs+len-newlen);                            // clear buffer end if necessary
             offs = 0;
         }
     }

src/StreamCore.cc

@@ -603,6 +603,7 @@ evalOut()
     // flush all unread input
     unparsedInput = false;
     inputBuffer.clear();
+    inputLine.clear();
     if (!formatOutput())
     {
         finishProtocol(FormatError);
@@ -1011,6 +1012,7 @@ readCallback(StreamIoStatus status,
             finishProtocol(Fault);
             return 0;
     }
+    inputHook(input, size);
     inputBuffer.append(input, size);
     debug("StreamCore::readCallback(%s) inputBuffer=\"%s\", size %" Z "u\n",
         name(), inputBuffer.expand()(), inputBuffer.length());

src/StreamCore.h

@@ -219,6 +219,7 @@ protected:
 
 // virtual methods
     virtual void protocolStartHook() {}
+    virtual void inputHook(const void* input, size_t size) {};
     virtual void protocolFinishHook(ProtocolResult) {}
     virtual void startTimer(unsigned long timeout) = 0;
     virtual bool formatValue(const StreamFormat&, const void* fieldaddress) = 0;

src/StreamEpics.cc

@@ -137,6 +137,7 @@ class Stream : protected StreamCore
 #endif
 
 // StreamCore methods
+    void inputHook(const void* input, size_t size);
     void protocolFinishHook(ProtocolResult);
     void startTimer(unsigned long timeout);
     bool getFieldAddress(const char* fieldname,
@@ -934,6 +935,10 @@ process()
     debug("Stream::process(%s) start\n", name());
     status = NO_ALARM;
     convert = OK;
+    if (record->tpro)
+    {
+        StreamDebugClass(record->name).print("start protocol '%s'\n", protocolname());
+    }
     if (!startProtocol(record->proc == 2 ? StreamCore::StartInit : StreamCore::StartNormal))
     {
         debug("Stream::process(%s): could not start %sprotocol, status=%s (%d)\n",
@@ -1028,11 +1033,26 @@ expire(const epicsTime&)
 
 // StreamCore virtual methods ////////////////////////////////////////////
 
+void Stream::
+inputHook(const void* input, size_t size)
+{
+    if (record->tpro > 1)
+    {
+        StreamDebugClass(record->name).print("received \"%s\"\n",
+            StreamBuffer(input, size).expand()());
+    }
+}
+
 void Stream::
 protocolFinishHook(ProtocolResult result)
 {
     debug("Stream::protocolFinishHook(%s, %s)\n",
         name(), toStr(result));
+    if (record->tpro)
+    {
+        StreamDebugClass(record->name).print("%s. out=\"%s\", in=\"%s\"\n",
+            toStr(result), outputLine.expand()(), inputLine.expand()());
+    }
     switch (result)
     {
         case Success:

src/StreamError.cc

@@ -171,8 +171,6 @@ print(const char* fmt, ...)
 {
     va_list args;
     va_start(args, fmt);
-    const char* f = strrchr(file, '/');
-    if (f) f++; else f = file;
     FILE* fp = StreamDebugFile ? StreamDebugFile : stderr;
     if (streamMsgTimeStamped)
     {
@@ -184,7 +182,13 @@ print(const char* fmt, ...)
     {
         fprintf(fp, "%s ", StreamGetThreadNameFunction());
     }
-    fprintf(fp, "%s:%d: ", f, line);
+    if (file) {
+        const char* f = strrchr(file, '/');
+        if (f) f++; else f = file;
+        fprintf(fp, "%s:", f);
+        if (line) fprintf(fp, "%d:", line);
+        fprintf(fp, " ");
+    }
     vfprintf(fp, fmt, args);
     fflush(fp);
     va_end(args);

src/StreamError.h

@@ -56,19 +56,15 @@ class StreamDebugClass
     const char* file;
     int line;
 public:
-    StreamDebugClass(const char* file, int line) :
+    StreamDebugClass(const char* file = NULL, int line = 0) :
         file(file), line(line) {}
     int print(const char* fmt, ...)
         __attribute__((__format__(__printf__,2,3)));
 };
 
-inline StreamDebugClass
-StreamDebugObject(const char* file, int line)
-{ return StreamDebugClass(file, line); }
-
 #define error StreamError
-#define debug (!streamDebug)?0:StreamDebugObject(__FILE__,__LINE__).print
+#define debug (!streamDebug)?0:StreamDebugClass(__FILE__,__LINE__).print
-#define debug2 (streamDebug<2)?0:StreamDebugObject(__FILE__,__LINE__).print
+#define debug2 (streamDebug<2)?0:StreamDebugClass(__FILE__,__LINE__).print
 
 /*
  * ANSI escape sequences for terminal output

streamApp/simple.proto

@@ -19,7 +19,7 @@
 # along with StreamDevice. If not, see https://www.gnu.org/licenses/.
 #########################################################################/
 
-terminator = CR LF;
+terminator = LF;
 
 cmd {
     out "%s";