From 601d4a37096a106f5fef7618d8eb76bde5c36860 Mon Sep 17 00:00:00 2001 From: Dirk Zimoch Date: Thu, 1 Jul 2021 16:52:28 +0200 Subject: [PATCH] shifted noisy debug from parser and I/O Intr to level 2 --- src/AsynDriverInterface.cc | 48 ++++++++++++++----------------- src/EnumConverter.cc | 4 +-- src/StreamError.h | 1 + src/StreamFormatConverter.cc | 2 -- src/StreamProtocol.cc | 55 ++++++++++++++++++------------------ 5 files changed, 52 insertions(+), 58 deletions(-) diff --git a/src/AsynDriverInterface.cc b/src/AsynDriverInterface.cc index 9b21e8a..28b80db 100644 --- a/src/AsynDriverInterface.cc +++ b/src/AsynDriverInterface.cc @@ -887,14 +887,11 @@ readHandler() if (pasynOctet->setInputEos(pvtOctet, pasynUser, deveos, (int)deveoslen) == asynSuccess) { - if (ioAction != AsyncRead) - { - debug("AsynDriverInterface::readHandler(%s) " - "input EOS changed from \"%s\" to \"%s\"\n", - clientName(), - StreamBuffer(oldeos, oldeoslen).expand()(), - StreamBuffer(deveos, deveoslen).expand()()); - } + debug2("AsynDriverInterface::readHandler(%s) " + "input EOS changed from \"%s\" to \"%s\"\n", + clientName(), + StreamBuffer(oldeos, oldeoslen).expand()(), + StreamBuffer(deveos, deveoslen).expand()()); break; } deveos++; deveoslen--; @@ -948,20 +945,18 @@ readHandler() eomReason = 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, buffer, bytesToRead, &received, &eomReason); - // Even though received is size_t I have seen (size_t)-1 here! - debug("AsynDriverInterface::readHandler(%s): " - "read returned %s: ioAction=%s received=%" Z "d, " - "eomReason=%s, buffer=\"%s\"\n", - clientName(), toStr(status), toStr(ioAction), - received, eomReasonToStr(eomReason), - StreamBuffer(buffer, received).expand()()); + // Even though received is size_t I have seen (size_t)-1 here + // in case half a terminator had been read last time! + if (!(status == asynTimeout && pasynUser->timeout == 0 && received == 0)) + debug("AsynDriverInterface::readHandler(%s): ioAction=%s " + "read(%" Z "u bytes, timeout=%g sec) returned status %s: received=%" Z "d bytes, " + "eomReason=%s, buffer=\"%s\"\n", + 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. // What about earlier versions? if (!connected) eomReason |= ASYN_EOM_END; @@ -1037,7 +1032,7 @@ readHandler() // reply timeout if (ioAction == AsyncRead) { - debug("AsynDriverInterface::readHandler(%s): " + debug2("AsynDriverInterface::readHandler(%s): " "no async input, retry in in %g seconds\n", clientName(), replyTimeout); // start next poll after timer expires @@ -1140,9 +1135,10 @@ readHandler() { pasynOctet->setInputEos(pvtOctet, pasynUser, oldeos, oldeoslen); - debug("AsynDriverInterface::readHandler(%s) " - "input EOS restored to \"%s\"\n", + debug2("AsynDriverInterface::readHandler(%s) " + "input EOS restored from \"%s\" to \"%s\"\n", clientName(), + StreamBuffer(deveos, deveoslen).expand()(), StreamBuffer(oldeos, oldeoslen).expand()()); } } @@ -1360,8 +1356,6 @@ timerExpired() // at the moment if another asynUser got input right now. // queueRequest might fail if another request was just queued pasynManager->isAutoConnect(pasynUser, &autoconnect); - debug("%s: polling for I/O Intr: autoconnected: %d, connect: %d\n", - clientName(), autoconnect, connected); if (autoconnect && !connected) { // has explicitely been disconnected @@ -1375,7 +1369,7 @@ timerExpired() asynStatus status = pasynManager->queueRequest(pasynUser, asynQueuePriorityLow, -1.0); // 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", clientName(), toStr(status), status!=asynSuccess ? pasynUser->errorMessage : ""); @@ -1493,7 +1487,7 @@ void AsynDriverInterface:: handleRequest() { cancelTimer(); - debug("AsynDriverInterface::handleRequest(%s) %s\n", + debug2("AsynDriverInterface::handleRequest(%s) %s\n", clientName(), toStr(ioAction)); switch (ioAction) { diff --git a/src/EnumConverter.cc b/src/EnumConverter.cc index 14c9678..a0cb657 100644 --- a/src/EnumConverter.cc +++ b/src/EnumConverter.cc @@ -76,7 +76,7 @@ parse(const StreamFormat& fmt, StreamBuffer& info, numEnums = -(numEnums+1); info.append('\0'); 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()()); return enum_format; } @@ -99,7 +99,7 @@ parse(const StreamFormat& fmt, StreamBuffer& info, if (*source++ == '}') { memcpy(info(n), &numEnums, sizeof(numEnums)); - debug("EnumConverter::parse %ld choices: %s\n", + debug2("EnumConverter::parse %ld choices: %s\n", numEnums, info.expand()()); return enum_format; } diff --git a/src/StreamError.h b/src/StreamError.h index ed0f9cb..361c295 100644 --- a/src/StreamError.h +++ b/src/StreamError.h @@ -68,6 +68,7 @@ StreamDebugObject(const char* file, int line) #define error StreamError #define debug (!streamDebug)?0:StreamDebugObject(__FILE__,__LINE__).print +#define debug2 (streamDebug<2)?0:StreamDebugObject(__FILE__,__LINE__).print /* * ANSI escape sequences for terminal output diff --git a/src/StreamFormatConverter.cc b/src/StreamFormatConverter.cc index a9b2998..57e0406 100644 --- a/src/StreamFormatConverter.cc +++ b/src/StreamFormatConverter.cc @@ -148,8 +148,6 @@ parseFormat(const char*& source, FormatType formatType, StreamFormat& streamForm error("Missing converter character\n"); return false; } - debug("StreamFormatConverter::parseFormat: converter='%c'\n", - streamFormat.conv); StreamFormatConverter* converter; converter = StreamFormatConverter::find(streamFormat.conv); if (!converter) diff --git a/src/StreamProtocol.cc b/src/StreamProtocol.cc index a60b6b0..48f1b31 100644 --- a/src/StreamProtocol.cc +++ b/src/StreamProtocol.cc @@ -189,6 +189,7 @@ readFile(const char* filename) if (file) { // file found; create a parser to read it + debug("StreamProtocolParser::readFile: found '%s'\n", dir()); parser = new StreamProtocolParser(file, filename); fclose(file); if (!parser->valid) return NULL; @@ -262,7 +263,7 @@ parseProtocol(Protocol& protocol, StreamBuffer* commands) startline = line; if (!readToken(token, " ,;{}=()$'\"", isGlobalContext(commands))) return false; - debug("StreamProtocolParser::parseProtocol:" + debug2("StreamProtocolParser::parseProtocol:" " token='%s'\n", token.expand()()); if (token[0] == 0) @@ -413,7 +414,7 @@ parseProtocol(Protocol& protocol, StreamBuffer* commands) error(line, filename(), "after command '%s'\n", token()); return false; } - debug("parseProtocol: command '%s'\n", (*commands).expand()()); + debug2("parseProtocol: command '%s'\n", (*commands).expand()()); commands->append('\0'); // terminate value with null byte } } @@ -468,7 +469,7 @@ Each time newline is read, line is incremented. if (c == '$') { // a variable - debug("StreamProtocolParser::readToken: Variable\n"); + debug2("StreamProtocolParser::readToken: Variable\n"); buffer.append(c); if (quote) buffer.append('"'); // mark as quoted variable c = getc(file); @@ -485,7 +486,7 @@ Each time newline is read, line is incremented. quote = false; // variable like ${xyz} if (!readToken(buffer, "{}=;")) return false; - debug("StreamProtocolParser::readToken: Variable '%s' in {}\n", + debug2("StreamProtocolParser::readToken: Variable '%s' in {}\n", buffer(token)); c = getc(file); if (c != '}') @@ -511,7 +512,7 @@ Each time newline is read, line is incremented. } else if (quote || c == '\'' || c == '"') { - debug("StreamProtocolParser::readToken: Quoted string\n"); + debug2("StreamProtocolParser::readToken: Quoted string\n"); // quoted string if (!quote) { @@ -570,13 +571,13 @@ Each time newline is read, line is incremented. } else if (strchr (specialchars, c)) { - debug("StreamProtocolParser::readToken: Special '%c'\n", c); + debug2("StreamProtocolParser::readToken: Special '%c'\n", c); // a single character buffer.append(c); return true; } // a word or (variable name) - debug("StreamProtocolParser::readToken: word\n"); + debug2("StreamProtocolParser::readToken: word\n"); while (1) { buffer.append(tolower(c)); @@ -587,7 +588,7 @@ Each time newline is read, line is incremented. break; } } - debug("StreamProtocolParser::readToken: word='%s' c='%c'\n", + debug2("StreamProtocolParser::readToken: word='%s' c='%c'\n", buffer(token), c); buffer.append('\0').append(&l, sizeof(l)); // append line number return true; @@ -615,7 +616,7 @@ parseValue(StreamBuffer& buffer, bool lazy) { token = buffer.length(); // start of next token if (!readToken(buffer)) return false; - debug("StreamProtocolParser::parseValue:%d: %s\n", + debug2("StreamProtocolParser::parseValue:%d: %s\n", line, buffer.expand(token)()); c = buffer[token]; if (c == '$') // a variable @@ -775,7 +776,7 @@ Protocol(const Protocol& p, StreamBuffer& name, int _line) parameter[0] = protocolname(); 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]); nextparameter = parameter[i] + strlen(parameter[i]) + 1; 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->value) return true; const char* source = pvar->value(); - debug("StreamProtocolParser::Protocol::getCommands" + debug2("StreamProtocolParser::Protocol::getCommands" "(handlername=\"%s\", client=\"%s\"): source=%s\n", handlername, client->name(), pvar->value.expand()()); if (!compileCommands(code, source, client)) @@ -945,15 +946,15 @@ getCommands(const char* handlername, StreamBuffer& code, Client* client) "in protocol '%s'\n", protocolname()); return false; } - debug("commands %s: %s\n", handlername, pvar->value.expand()()); - debug("compiled to: %s\n", code.expand()()); + debug2("commands %s: %s\n", handlername, pvar->value.expand()()); + debug2("compiled to: %s\n", code.expand()()); return true; } bool StreamProtocolParser::Protocol:: replaceVariable(StreamBuffer& buffer, const char* varname) { - debug("StreamProtocolParser::Protocol::replaceVariable %s\n", varname); + debug2("StreamProtocolParser::Protocol::replaceVariable %s\n", varname); bool quoted = false; if (*++varname == '"') { @@ -1033,16 +1034,16 @@ compileNumber(unsigned long& number, const char*& source, unsigned long max) unsigned long n; StreamBuffer buffer; - debug("StreamProtocolParser::Protocol::compileNumber source=\"%s\"\n", + debug2("StreamProtocolParser::Protocol::compileNumber source=\"%s\"\n", source); 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); if (*source == '$') { if (!replaceVariable(buffer, source)) return false; - debug("buffer=%s\n", buffer.expand()()); + debug2("buffer=%s\n", buffer.expand()()); buffer.truncate(-1-(int)sizeof(int)); } else @@ -1077,7 +1078,7 @@ compileNumber(unsigned long& number, const char*& source, unsigned long max) return false; } number = n; - debug("StreamProtocolParser::Protocol::compileNumber %s = %ld\n", + debug2("StreamProtocolParser::Protocol::compileNumber %s = %ld\n", buffer(), n); return true; } @@ -1095,7 +1096,7 @@ compileString(StreamBuffer& buffer, const char*& source, size_t formatpos = buffer.length(); line = getLineNumber(source); - debug("StreamProtocolParser::Protocol::compileString " + debug2("StreamProtocolParser::Protocol::compileString " "line %d source=\"%s\" formatType=%s quoted=%i recursionDepth=%d\n", line, source, ::toStr(formatType), quoted, recursionDepth); @@ -1110,7 +1111,7 @@ compileString(StreamBuffer& buffer, const char*& source, // this is step 2: replacing the formats 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 // We do this here after all variables in this line // have been replaced and after string has been coded. @@ -1133,7 +1134,7 @@ compileString(StreamBuffer& buffer, const char*& source, formatpos+=2; continue; } - debug("StreamProtocolParser::Protocol::compileString " + debug2("StreamProtocolParser::Protocol::compileString " "format=\"%s\"\n", buffer.expand(formatpos)()); nformats++; formatbuffer.clear(); @@ -1150,14 +1151,14 @@ compileString(StreamBuffer& buffer, const char*& source, } size_t formatlen = p - buffer(formatpos); buffer.replace(formatpos, formatlen, formatbuffer); - debug("StreamProtocolParser::Protocol::compileString " + debug2("StreamProtocolParser::Protocol::compileString " "replaced by: \"%s\"\n", buffer.expand(formatpos)()); formatpos += formatbuffer.length(); continue; } formatpos ++; } - debug("StreamProtocolParser::Protocol::compileString " + debug2("StreamProtocolParser::Protocol::compileString " "%d formats found in line %d\n", nformats, line); } if (!*source) break; @@ -1400,7 +1401,7 @@ compileString(StreamBuffer& buffer, const char*& source, "Unexpected '%s' in string\n", source); return false; } - debug("StreamProtocolParser::Protocol::compileString buffer=%s\n", buffer.expand()()); + debug2("StreamProtocolParser::Protocol::compileString buffer=%s\n", buffer.expand()()); return true; } @@ -1446,7 +1447,7 @@ compileFormat(StreamBuffer& buffer, const char*& formatstr, // add fieldname for debug purpose fieldname=buffer.length(); buffer.append(source, fieldnameEnd - source).append(eos); - debug("StreamProtocolParser::Protocol::compileFormat: fieldname='%s'\n", + debug2("StreamProtocolParser::Protocol::compileFormat: fieldname='%s'\n", buffer(fieldname)); StreamBuffer fieldAddress; if (!client->getFieldAddress(buffer(fieldname), fieldAddress)) @@ -1507,14 +1508,14 @@ compileFormat(StreamBuffer& buffer, const char*& formatstr, // add formatstr for debug purpose 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()()); // add streamFormat structure and info buffer.append(&streamFormat, sizeof(streamFormat)); buffer.append(infoString); - debug("StreamProtocolParser::Protocol::compileFormat: format.type=%s, " + debug2("StreamProtocolParser::Protocol::compileFormat: format.type=%s, " "infolen=%ld infostring=\"%s\"\n", StreamFormatTypeStr[streamFormat.type], streamFormat.infolen, infoString.expand()());