shifted noisy debug from parser and I/O Intr to level 2

This commit is contained in:
2021-07-01 16:52:28 +02:00
parent f495dd9853
commit 601d4a3709
5 changed files with 52 additions and 58 deletions

View File

@ -887,14 +887,11 @@ readHandler()
if (pasynOctet->setInputEos(pvtOctet, pasynUser, if (pasynOctet->setInputEos(pvtOctet, pasynUser,
deveos, (int)deveoslen) == asynSuccess) deveos, (int)deveoslen) == asynSuccess)
{ {
if (ioAction != AsyncRead) debug2("AsynDriverInterface::readHandler(%s) "
{ "input EOS changed from \"%s\" to \"%s\"\n",
debug("AsynDriverInterface::readHandler(%s) " clientName(),
"input EOS changed from \"%s\" to \"%s\"\n", StreamBuffer(oldeos, oldeoslen).expand()(),
clientName(), StreamBuffer(deveos, deveoslen).expand()());
StreamBuffer(oldeos, oldeoslen).expand()(),
StreamBuffer(deveos, deveoslen).expand()());
}
break; break;
} }
deveos++; deveoslen--; deveos++; deveoslen--;
@ -948,20 +945,18 @@ readHandler()
eomReason = 0; eomReason = 0;
pasynUser->errorMessage[0] = 0; pasynUser->errorMessage[0] = 0;
debug("AsynDriverInterface::readHandler(%s): ioAction=%s "
"read(..., bytesToRead=%" Z "u, ...) "
"[timeout=%g sec]\n",
clientName(), toStr(ioAction),
bytesToRead, pasynUser->timeout);
status = pasynOctet->read(pvtOctet, pasynUser, status = pasynOctet->read(pvtOctet, pasynUser,
buffer, bytesToRead, &received, &eomReason); buffer, bytesToRead, &received, &eomReason);
// Even though received is size_t I have seen (size_t)-1 here! // Even though received is size_t I have seen (size_t)-1 here
debug("AsynDriverInterface::readHandler(%s): " // in case half a terminator had been read last time!
"read returned %s: ioAction=%s received=%" Z "d, " if (!(status == asynTimeout && pasynUser->timeout == 0 && received == 0))
"eomReason=%s, buffer=\"%s\"\n", debug("AsynDriverInterface::readHandler(%s): ioAction=%s "
clientName(), toStr(status), toStr(ioAction), "read(%" Z "u bytes, timeout=%g sec) returned status %s: received=%" Z "d bytes, "
received, eomReasonToStr(eomReason), "eomReason=%s, buffer=\"%s\"\n",
StreamBuffer(buffer, received).expand()()); clientName(), toStr(ioAction),
bytesToRead, pasynUser->timeout, toStr(status), received,
eomReasonToStr(eomReason), StreamBuffer(buffer, received).expand()());
// asyn 4.16 sets reason to ASYN_EOM_END when device disconnects. // asyn 4.16 sets reason to ASYN_EOM_END when device disconnects.
// What about earlier versions? // What about earlier versions?
if (!connected) eomReason |= ASYN_EOM_END; if (!connected) eomReason |= ASYN_EOM_END;
@ -1037,7 +1032,7 @@ readHandler()
// reply timeout // reply timeout
if (ioAction == AsyncRead) if (ioAction == AsyncRead)
{ {
debug("AsynDriverInterface::readHandler(%s): " debug2("AsynDriverInterface::readHandler(%s): "
"no async input, retry in in %g seconds\n", "no async input, retry in in %g seconds\n",
clientName(), replyTimeout); clientName(), replyTimeout);
// start next poll after timer expires // start next poll after timer expires
@ -1140,9 +1135,10 @@ readHandler()
{ {
pasynOctet->setInputEos(pvtOctet, pasynUser, pasynOctet->setInputEos(pvtOctet, pasynUser,
oldeos, oldeoslen); oldeos, oldeoslen);
debug("AsynDriverInterface::readHandler(%s) " debug2("AsynDriverInterface::readHandler(%s) "
"input EOS restored to \"%s\"\n", "input EOS restored from \"%s\" to \"%s\"\n",
clientName(), clientName(),
StreamBuffer(deveos, deveoslen).expand()(),
StreamBuffer(oldeos, oldeoslen).expand()()); StreamBuffer(oldeos, oldeoslen).expand()());
} }
} }
@ -1360,8 +1356,6 @@ timerExpired()
// at the moment if another asynUser got input right now. // at the moment if another asynUser got input right now.
// queueRequest might fail if another request was just queued // queueRequest might fail if another request was just queued
pasynManager->isAutoConnect(pasynUser, &autoconnect); pasynManager->isAutoConnect(pasynUser, &autoconnect);
debug("%s: polling for I/O Intr: autoconnected: %d, connect: %d\n",
clientName(), autoconnect, connected);
if (autoconnect && !connected) if (autoconnect && !connected)
{ {
// has explicitely been disconnected // has explicitely been disconnected
@ -1375,7 +1369,7 @@ timerExpired()
asynStatus status = pasynManager->queueRequest(pasynUser, asynStatus status = pasynManager->queueRequest(pasynUser,
asynQueuePriorityLow, -1.0); asynQueuePriorityLow, -1.0);
// if this fails, we are already queued by another thread // if this fails, we are already queued by another thread
debug("AsynDriverInterface::timerExpired %s: " debug2("AsynDriverInterface::timerExpired %s: "
"queueRequest(..., priority=Low, queueTimeout=-1) = %s %s\n", "queueRequest(..., priority=Low, queueTimeout=-1) = %s %s\n",
clientName(), toStr(status), clientName(), toStr(status),
status!=asynSuccess ? pasynUser->errorMessage : ""); status!=asynSuccess ? pasynUser->errorMessage : "");
@ -1493,7 +1487,7 @@ void AsynDriverInterface::
handleRequest() handleRequest()
{ {
cancelTimer(); cancelTimer();
debug("AsynDriverInterface::handleRequest(%s) %s\n", debug2("AsynDriverInterface::handleRequest(%s) %s\n",
clientName(), toStr(ioAction)); clientName(), toStr(ioAction));
switch (ioAction) switch (ioAction)
{ {

View File

@ -76,7 +76,7 @@ parse(const StreamFormat& fmt, StreamBuffer& info,
numEnums = -(numEnums+1); numEnums = -(numEnums+1);
info.append('\0'); info.append('\0');
memcpy(info(n), &numEnums, sizeof(numEnums)); memcpy(info(n), &numEnums, sizeof(numEnums));
debug("EnumConverter::parse %ld choices with default: %s\n", debug2("EnumConverter::parse %ld choices with default: %s\n",
-numEnums, info.expand()()); -numEnums, info.expand()());
return enum_format; return enum_format;
} }
@ -99,7 +99,7 @@ parse(const StreamFormat& fmt, StreamBuffer& info,
if (*source++ == '}') if (*source++ == '}')
{ {
memcpy(info(n), &numEnums, sizeof(numEnums)); memcpy(info(n), &numEnums, sizeof(numEnums));
debug("EnumConverter::parse %ld choices: %s\n", debug2("EnumConverter::parse %ld choices: %s\n",
numEnums, info.expand()()); numEnums, info.expand()());
return enum_format; return enum_format;
} }

View File

@ -68,6 +68,7 @@ StreamDebugObject(const char* file, int line)
#define error StreamError #define error StreamError
#define debug (!streamDebug)?0:StreamDebugObject(__FILE__,__LINE__).print #define debug (!streamDebug)?0:StreamDebugObject(__FILE__,__LINE__).print
#define debug2 (streamDebug<2)?0:StreamDebugObject(__FILE__,__LINE__).print
/* /*
* ANSI escape sequences for terminal output * ANSI escape sequences for terminal output

View File

@ -148,8 +148,6 @@ parseFormat(const char*& source, FormatType formatType, StreamFormat& streamForm
error("Missing converter character\n"); error("Missing converter character\n");
return false; return false;
} }
debug("StreamFormatConverter::parseFormat: converter='%c'\n",
streamFormat.conv);
StreamFormatConverter* converter; StreamFormatConverter* converter;
converter = StreamFormatConverter::find(streamFormat.conv); converter = StreamFormatConverter::find(streamFormat.conv);
if (!converter) if (!converter)

View File

@ -189,6 +189,7 @@ readFile(const char* filename)
if (file) if (file)
{ {
// file found; create a parser to read it // file found; create a parser to read it
debug("StreamProtocolParser::readFile: found '%s'\n", dir());
parser = new StreamProtocolParser(file, filename); parser = new StreamProtocolParser(file, filename);
fclose(file); fclose(file);
if (!parser->valid) return NULL; if (!parser->valid) return NULL;
@ -262,7 +263,7 @@ parseProtocol(Protocol& protocol, StreamBuffer* commands)
startline = line; startline = line;
if (!readToken(token, " ,;{}=()$'\"", isGlobalContext(commands))) if (!readToken(token, " ,;{}=()$'\"", isGlobalContext(commands)))
return false; return false;
debug("StreamProtocolParser::parseProtocol:" debug2("StreamProtocolParser::parseProtocol:"
" token='%s'\n", token.expand()()); " token='%s'\n", token.expand()());
if (token[0] == 0) if (token[0] == 0)
@ -413,7 +414,7 @@ parseProtocol(Protocol& protocol, StreamBuffer* commands)
error(line, filename(), "after command '%s'\n", token()); error(line, filename(), "after command '%s'\n", token());
return false; return false;
} }
debug("parseProtocol: command '%s'\n", (*commands).expand()()); debug2("parseProtocol: command '%s'\n", (*commands).expand()());
commands->append('\0'); // terminate value with null byte commands->append('\0'); // terminate value with null byte
} }
} }
@ -468,7 +469,7 @@ Each time newline is read, line is incremented.
if (c == '$') if (c == '$')
{ {
// a variable // a variable
debug("StreamProtocolParser::readToken: Variable\n"); debug2("StreamProtocolParser::readToken: Variable\n");
buffer.append(c); buffer.append(c);
if (quote) buffer.append('"'); // mark as quoted variable if (quote) buffer.append('"'); // mark as quoted variable
c = getc(file); c = getc(file);
@ -485,7 +486,7 @@ Each time newline is read, line is incremented.
quote = false; quote = false;
// variable like ${xyz} // variable like ${xyz}
if (!readToken(buffer, "{}=;")) return false; if (!readToken(buffer, "{}=;")) return false;
debug("StreamProtocolParser::readToken: Variable '%s' in {}\n", debug2("StreamProtocolParser::readToken: Variable '%s' in {}\n",
buffer(token)); buffer(token));
c = getc(file); c = getc(file);
if (c != '}') if (c != '}')
@ -511,7 +512,7 @@ Each time newline is read, line is incremented.
} }
else if (quote || c == '\'' || c == '"') else if (quote || c == '\'' || c == '"')
{ {
debug("StreamProtocolParser::readToken: Quoted string\n"); debug2("StreamProtocolParser::readToken: Quoted string\n");
// quoted string // quoted string
if (!quote) if (!quote)
{ {
@ -570,13 +571,13 @@ Each time newline is read, line is incremented.
} }
else if (strchr (specialchars, c)) else if (strchr (specialchars, c))
{ {
debug("StreamProtocolParser::readToken: Special '%c'\n", c); debug2("StreamProtocolParser::readToken: Special '%c'\n", c);
// a single character // a single character
buffer.append(c); buffer.append(c);
return true; return true;
} }
// a word or (variable name) // a word or (variable name)
debug("StreamProtocolParser::readToken: word\n"); debug2("StreamProtocolParser::readToken: word\n");
while (1) while (1)
{ {
buffer.append(tolower(c)); buffer.append(tolower(c));
@ -587,7 +588,7 @@ Each time newline is read, line is incremented.
break; break;
} }
} }
debug("StreamProtocolParser::readToken: word='%s' c='%c'\n", debug2("StreamProtocolParser::readToken: word='%s' c='%c'\n",
buffer(token), c); buffer(token), c);
buffer.append('\0').append(&l, sizeof(l)); // append line number buffer.append('\0').append(&l, sizeof(l)); // append line number
return true; return true;
@ -615,7 +616,7 @@ parseValue(StreamBuffer& buffer, bool lazy)
{ {
token = buffer.length(); // start of next token token = buffer.length(); // start of next token
if (!readToken(buffer)) return false; if (!readToken(buffer)) return false;
debug("StreamProtocolParser::parseValue:%d: %s\n", debug2("StreamProtocolParser::parseValue:%d: %s\n",
line, buffer.expand(token)()); line, buffer.expand(token)());
c = buffer[token]; c = buffer[token];
if (c == '$') // a variable if (c == '$') // a variable
@ -775,7 +776,7 @@ Protocol(const Protocol& p, StreamBuffer& name, int _line)
parameter[0] = protocolname(); parameter[0] = protocolname();
for (i = 0; i < 9; i++) for (i = 0; i < 9; i++)
{ {
debug("StreamProtocolParser::Protocol::Protocol $%d=\"%s\"\n", if (i) debug("StreamProtocolParser::Protocol::Protocol $%d=\"%s\"\n",
i, parameter[i]); i, parameter[i]);
nextparameter = parameter[i] + strlen(parameter[i]) + 1; nextparameter = parameter[i] + strlen(parameter[i]) + 1;
if (nextparameter > name.length() + parameter[0]) break; if (nextparameter > name.length() + parameter[0]) break;
@ -928,7 +929,7 @@ getCommands(const char* handlername, StreamBuffer& code, Client* client)
if (!pvar) return true; if (!pvar) return true;
if (!pvar->value) return true; if (!pvar->value) return true;
const char* source = pvar->value(); const char* source = pvar->value();
debug("StreamProtocolParser::Protocol::getCommands" debug2("StreamProtocolParser::Protocol::getCommands"
"(handlername=\"%s\", client=\"%s\"): source=%s\n", "(handlername=\"%s\", client=\"%s\"): source=%s\n",
handlername, client->name(), pvar->value.expand()()); handlername, client->name(), pvar->value.expand()());
if (!compileCommands(code, source, client)) if (!compileCommands(code, source, client))
@ -945,15 +946,15 @@ getCommands(const char* handlername, StreamBuffer& code, Client* client)
"in protocol '%s'\n", protocolname()); "in protocol '%s'\n", protocolname());
return false; return false;
} }
debug("commands %s: %s\n", handlername, pvar->value.expand()()); debug2("commands %s: %s\n", handlername, pvar->value.expand()());
debug("compiled to: %s\n", code.expand()()); debug2("compiled to: %s\n", code.expand()());
return true; return true;
} }
bool StreamProtocolParser::Protocol:: bool StreamProtocolParser::Protocol::
replaceVariable(StreamBuffer& buffer, const char* varname) replaceVariable(StreamBuffer& buffer, const char* varname)
{ {
debug("StreamProtocolParser::Protocol::replaceVariable %s\n", varname); debug2("StreamProtocolParser::Protocol::replaceVariable %s\n", varname);
bool quoted = false; bool quoted = false;
if (*++varname == '"') if (*++varname == '"')
{ {
@ -1033,16 +1034,16 @@ compileNumber(unsigned long& number, const char*& source, unsigned long max)
unsigned long n; unsigned long n;
StreamBuffer buffer; StreamBuffer buffer;
debug("StreamProtocolParser::Protocol::compileNumber source=\"%s\"\n", debug2("StreamProtocolParser::Protocol::compileNumber source=\"%s\"\n",
source); source);
while (*source == '$' || (*source >= '0' && *source <= '9')) while (*source == '$' || (*source >= '0' && *source <= '9'))
{ {
debug("StreamProtocolParser::Protocol::compileNumber *source=%u source=\"%s\"\n", debug2("StreamProtocolParser::Protocol::compileNumber *source=%u source=\"%s\"\n",
*source, source); *source, source);
if (*source == '$') if (*source == '$')
{ {
if (!replaceVariable(buffer, source)) return false; if (!replaceVariable(buffer, source)) return false;
debug("buffer=%s\n", buffer.expand()()); debug2("buffer=%s\n", buffer.expand()());
buffer.truncate(-1-(int)sizeof(int)); buffer.truncate(-1-(int)sizeof(int));
} }
else else
@ -1077,7 +1078,7 @@ compileNumber(unsigned long& number, const char*& source, unsigned long max)
return false; return false;
} }
number = n; number = n;
debug("StreamProtocolParser::Protocol::compileNumber %s = %ld\n", debug2("StreamProtocolParser::Protocol::compileNumber %s = %ld\n",
buffer(), n); buffer(), n);
return true; return true;
} }
@ -1095,7 +1096,7 @@ compileString(StreamBuffer& buffer, const char*& source,
size_t formatpos = buffer.length(); size_t formatpos = buffer.length();
line = getLineNumber(source); line = getLineNumber(source);
debug("StreamProtocolParser::Protocol::compileString " debug2("StreamProtocolParser::Protocol::compileString "
"line %d source=\"%s\" formatType=%s quoted=%i recursionDepth=%d\n", "line %d source=\"%s\" formatType=%s quoted=%i recursionDepth=%d\n",
line, source, ::toStr(formatType), quoted, recursionDepth); line, source, ::toStr(formatType), quoted, recursionDepth);
@ -1110,7 +1111,7 @@ compileString(StreamBuffer& buffer, const char*& source,
// this is step 2: replacing the formats // this is step 2: replacing the formats
if (!*source || (newline = getLineNumber(source)) != line) if (!*source || (newline = getLineNumber(source)) != line)
{ {
debug("StreamProtocolParser::Protocol::compileString line %i: %s\n", line, buffer.expand()()); debug2("StreamProtocolParser::Protocol::compileString line %i: %s\n", line, buffer.expand()());
// compile all formats in this line // compile all formats in this line
// We do this here after all variables in this line // We do this here after all variables in this line
// have been replaced and after string has been coded. // have been replaced and after string has been coded.
@ -1133,7 +1134,7 @@ compileString(StreamBuffer& buffer, const char*& source,
formatpos+=2; formatpos+=2;
continue; continue;
} }
debug("StreamProtocolParser::Protocol::compileString " debug2("StreamProtocolParser::Protocol::compileString "
"format=\"%s\"\n", buffer.expand(formatpos)()); "format=\"%s\"\n", buffer.expand(formatpos)());
nformats++; nformats++;
formatbuffer.clear(); formatbuffer.clear();
@ -1150,14 +1151,14 @@ compileString(StreamBuffer& buffer, const char*& source,
} }
size_t formatlen = p - buffer(formatpos); size_t formatlen = p - buffer(formatpos);
buffer.replace(formatpos, formatlen, formatbuffer); buffer.replace(formatpos, formatlen, formatbuffer);
debug("StreamProtocolParser::Protocol::compileString " debug2("StreamProtocolParser::Protocol::compileString "
"replaced by: \"%s\"\n", buffer.expand(formatpos)()); "replaced by: \"%s\"\n", buffer.expand(formatpos)());
formatpos += formatbuffer.length(); formatpos += formatbuffer.length();
continue; continue;
} }
formatpos ++; formatpos ++;
} }
debug("StreamProtocolParser::Protocol::compileString " debug2("StreamProtocolParser::Protocol::compileString "
"%d formats found in line %d\n", nformats, line); "%d formats found in line %d\n", nformats, line);
} }
if (!*source) break; if (!*source) break;
@ -1400,7 +1401,7 @@ compileString(StreamBuffer& buffer, const char*& source,
"Unexpected '%s' in string\n", source); "Unexpected '%s' in string\n", source);
return false; return false;
} }
debug("StreamProtocolParser::Protocol::compileString buffer=%s\n", buffer.expand()()); debug2("StreamProtocolParser::Protocol::compileString buffer=%s\n", buffer.expand()());
return true; return true;
} }
@ -1446,7 +1447,7 @@ compileFormat(StreamBuffer& buffer, const char*& formatstr,
// add fieldname for debug purpose // add fieldname for debug purpose
fieldname=buffer.length(); fieldname=buffer.length();
buffer.append(source, fieldnameEnd - source).append(eos); buffer.append(source, fieldnameEnd - source).append(eos);
debug("StreamProtocolParser::Protocol::compileFormat: fieldname='%s'\n", debug2("StreamProtocolParser::Protocol::compileFormat: fieldname='%s'\n",
buffer(fieldname)); buffer(fieldname));
StreamBuffer fieldAddress; StreamBuffer fieldAddress;
if (!client->getFieldAddress(buffer(fieldname), fieldAddress)) if (!client->getFieldAddress(buffer(fieldname), fieldAddress))
@ -1507,14 +1508,14 @@ compileFormat(StreamBuffer& buffer, const char*& formatstr,
// add formatstr for debug purpose // add formatstr for debug purpose
buffer.append(formatstart, source-formatstart).append(eos); buffer.append(formatstart, source-formatstart).append(eos);
debug("StreamProtocolParser::Protocol::compileFormat: formatstring=\"%s\"\n", debug2("StreamProtocolParser::Protocol::compileFormat: formatstring=\"%s\"\n",
StreamBuffer(formatstart, source-formatstart).expand()()); StreamBuffer(formatstart, source-formatstart).expand()());
// add streamFormat structure and info // add streamFormat structure and info
buffer.append(&streamFormat, sizeof(streamFormat)); buffer.append(&streamFormat, sizeof(streamFormat));
buffer.append(infoString); buffer.append(infoString);
debug("StreamProtocolParser::Protocol::compileFormat: format.type=%s, " debug2("StreamProtocolParser::Protocol::compileFormat: format.type=%s, "
"infolen=%ld infostring=\"%s\"\n", "infolen=%ld infostring=\"%s\"\n",
StreamFormatTypeStr[streamFormat.type], StreamFormatTypeStr[streamFormat.type],
streamFormat.infolen, infoString.expand()()); streamFormat.infolen, infoString.expand()());