From 3497e2be6a7e1623ac9b3d81879909d68b755ce1 Mon Sep 17 00:00:00 2001 From: Huang-Ming Huang Date: Sat, 6 Jun 2026 06:33:06 -0500 Subject: [PATCH 1/4] Bound transaction trace polling in test harness --- tests/TestHarness/queries.py | 22 ++++++++++++++++----- tests/TestHarness/testUtils.py | 36 ++++++++++++++++++++++------------ 2 files changed, 41 insertions(+), 17 deletions(-) diff --git a/tests/TestHarness/queries.py b/tests/TestHarness/queries.py index 7953f6178f..c7edca9dda 100644 --- a/tests/TestHarness/queries.py +++ b/tests/TestHarness/queries.py @@ -240,6 +240,7 @@ def isBlockFinalized(self, blockNum): return self.isBlockPresent(blockNum, blockType=BlockType.lib) def getTransaction(self, transId, silentErrors=False, exitOnError=False, delayedRetry=True): + """Fetch a transaction trace, bounding each poll so missing traces cannot stall bootstrap.""" assert(isinstance(transId, str)) exitOnErrorForDelayed=not delayedRetry and exitOnError timeout=3 @@ -247,7 +248,7 @@ def getTransaction(self, transId, silentErrors=False, exitOnError=False, delayed cmd="%s %s" % (cmdDesc, transId) msg="(transaction id=%s)" % (transId); for i in range(0,(int(60/timeout) - 1)): - trans=self.processClioCmd(cmd, cmdDesc, silentErrors=True, exitOnError=exitOnErrorForDelayed, exitMsg=msg) + trans=self.processClioCmd(cmd, cmdDesc, silentErrors=True, exitOnError=exitOnErrorForDelayed, exitMsg=msg, timeout=timeout) if trans is not None or not delayedRetry: return trans if Utils.Debug: Utils.Print("Could not find transaction with id %s, delay and retry" % (transId)) @@ -255,7 +256,7 @@ def getTransaction(self, transId, silentErrors=False, exitOnError=False, delayed self.missingTransaction=True # either it is there or the transaction has timed out - return self.processClioCmd(cmd, cmdDesc, silentErrors=silentErrors, exitOnError=exitOnError, exitMsg=msg) + return self.processClioCmd(cmd, cmdDesc, silentErrors=silentErrors, exitOnError=exitOnError, exitMsg=msg, timeout=timeout) def isTransInBlock(self, transId, blockId, exitOnError=False): """Check if transId is within block identified by blockId""" @@ -561,7 +562,8 @@ def getTableColumns(self, contract, scope, table): keys=list(row["value"].keys()) return keys - def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exitMsg=None, returnType=ReturnType.json): + def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exitMsg=None, returnType=ReturnType.json, timeout=None): + """Run clio and decode the requested return type, optionally bounding the subprocess runtime.""" assert(isinstance(returnType, ReturnType)) cmd="%s %s %s" % (Utils.SysClientPath, self.sysClientArgs(), cmd) if Utils.Debug: Utils.Print("cmd: %s" % (cmd)) @@ -576,9 +578,9 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi retries -= 1 try: if returnType==ReturnType.json: - trans=Utils.runCmdReturnJson(cmd, silentErrors=silentErrors) + trans=Utils.runCmdReturnJson(cmd, silentErrors=silentErrors, timeout=timeout) elif returnType==ReturnType.raw: - trans=Utils.runCmdReturnStr(cmd) + trans=Utils.runCmdReturnStr(cmd, timeout=timeout) else: unhandledEnumType(returnType) @@ -600,6 +602,16 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi else: Utils.Print("ERROR: %s" % (errorMsg)) return None + except subprocess.TimeoutExpired as ex: + if not silentErrors: + end=time.perf_counter() + errorMsg="Timeout during \"%s\" after %.3f sec. cmd timeout=%s. %s" % (cmdDesc, end-start, ex.timeout, exitMsg) + if exitOnError: + Utils.cmdError(errorMsg) + Utils.errorExit(errorMsg) + else: + Utils.Print("ERROR: %s" % (errorMsg)) + return None break if exitOnError and trans is None: diff --git a/tests/TestHarness/testUtils.py b/tests/TestHarness/testUtils.py index 3209fdaba2..8d701a934e 100644 --- a/tests/TestHarness/testUtils.py +++ b/tests/TestHarness/testUtils.py @@ -197,9 +197,10 @@ def getChainStrategies(): return chainSyncStrategies @staticmethod - def checkOutput(cmd, ignoreError=False): + def checkOutput(cmd, ignoreError=False, timeout=None): + """Run a command and return stdout, optionally bounding the subprocess runtime.""" popen = Utils.delayedCheckOutput(cmd) - return Utils.checkDelayedOutput(popen, cmd, ignoreError=ignoreError) + return Utils.checkDelayedOutput(popen, cmd, ignoreError=ignoreError, timeout=timeout) @staticmethod def delayedCheckOutput(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE): @@ -210,11 +211,18 @@ def delayedCheckOutput(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE): return popen @staticmethod - def checkDelayedOutput(popen, cmd, ignoreError=False): + def checkDelayedOutput(popen, cmd, ignoreError=False, timeout=None): + """Collect a subprocess result and terminate it if it exceeds the requested timeout.""" assert isinstance(popen, subprocess.Popen) assert isinstance(cmd, (str,list)) start=Utils.timestamp() - (output,error)=popen.communicate() + try: + (output,error)=popen.communicate(timeout=timeout) + except subprocess.TimeoutExpired as ex: + popen.kill() + (output,error)=popen.communicate() + Utils.checkOutputFileWrite(start, cmd, output, error) + raise subprocess.TimeoutExpired(cmd=cmd, timeout=ex.timeout, output=output, stderr=error) Utils.checkOutputFileWrite(start, cmd, output, error) if popen.returncode != 0 and not ignoreError: raise subprocess.CalledProcessError(returncode=popen.returncode, cmd=cmd, output=output, stderr=error) @@ -315,25 +323,29 @@ def toJson(retStr, trace=False, silentErrors=True): raise @staticmethod - def runCmdArrReturnJson(cmdArr, trace=False, silentErrors=True): - retStr=Utils.checkOutput(cmdArr) + def runCmdArrReturnJson(cmdArr, trace=False, silentErrors=True, timeout=None): + """Run a command array and parse its JSON output, optionally with a subprocess timeout.""" + retStr=Utils.checkOutput(cmdArr, timeout=timeout) return Utils.toJson(retStr, trace, silentErrors) @staticmethod - def runCmdReturnStr(cmd, trace=False, ignoreError=False): + def runCmdReturnStr(cmd, trace=False, ignoreError=False, timeout=None): + """Run a shell command string and return stdout, optionally with a subprocess timeout.""" cmdArr=shlex.split(cmd) - return Utils.runCmdArrReturnStr(cmdArr, ignoreError=ignoreError) + return Utils.runCmdArrReturnStr(cmdArr, ignoreError=ignoreError, timeout=timeout) @staticmethod - def runCmdArrReturnStr(cmdArr, trace=False, ignoreError=False): - retStr=Utils.checkOutput(cmdArr, ignoreError=ignoreError) + def runCmdArrReturnStr(cmdArr, trace=False, ignoreError=False, timeout=None): + """Run a command array and return stdout, optionally with a subprocess timeout.""" + retStr=Utils.checkOutput(cmdArr, ignoreError=ignoreError, timeout=timeout) if trace: Utils.Print ("RAW > %s" % (retStr)) return retStr @staticmethod - def runCmdReturnJson(cmd, trace=False, silentErrors=False): + def runCmdReturnJson(cmd, trace=False, silentErrors=False, timeout=None): + """Run a shell command string and parse its JSON output, optionally with a subprocess timeout.""" cmdArr=shlex.split(cmd) - return Utils.runCmdArrReturnJson(cmdArr, trace=trace, silentErrors=silentErrors) + return Utils.runCmdArrReturnJson(cmdArr, trace=trace, silentErrors=silentErrors, timeout=timeout) @staticmethod def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exitMsg=None): From e1a8f414a30a0dc6bda3351e97372fd4d577f084 Mon Sep 17 00:00:00 2001 From: Huang-Ming Huang Date: Sat, 6 Jun 2026 13:10:18 -0500 Subject: [PATCH 2/4] Bound action push subprocess in test harness --- tests/TestHarness/transactions.py | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/tests/TestHarness/transactions.py b/tests/TestHarness/transactions.py index 8ec27bcee5..1934c8a400 100644 --- a/tests/TestHarness/transactions.py +++ b/tests/TestHarness/transactions.py @@ -12,6 +12,8 @@ class Transactions(NodeopQueries): retry_num_blocks_default = 1 + # Default clio action-push timeout, in seconds, used to keep intentionally interrupting transactions bounded. + push_message_timeout_default = 45 def __init__(self, host, port, walletMgr=None): super().__init__(host, port, walletMgr) @@ -261,7 +263,9 @@ def pushTransaction(self, trans, opts="", silentErrors=False, permissions=None): return (False, msg) # returns tuple with transaction execution status and transaction - def pushMessage(self, account, action, data, opts, silentErrors=False, signatures=None, expectTrxTrace=True): + def pushMessage(self, account, action, data, opts, silentErrors=False, signatures=None, expectTrxTrace=True, + timeout=push_message_timeout_default): + """Push an action with clio, bounding the clio subprocess runtime by default.""" cmd="%s %s push action -j %s %s" % (Utils.SysClientPath, self.sysClientArgs(), account, action) cmdArr=cmd.split() # not using sign_str, since cmdArr messes up the string @@ -278,7 +282,7 @@ def pushMessage(self, account, action, data, opts, silentErrors=False, signature while retries > 0: retries -= 1 try: - trans=Utils.runCmdArrReturnJson(cmdArr) + trans=Utils.runCmdArrReturnJson(cmdArr, timeout=timeout) self.trackCmdTransaction(trans, ignoreNonTrans=True) if Utils.Debug: end=time.perf_counter() @@ -294,6 +298,12 @@ def pushMessage(self, account, action, data, opts, silentErrors=False, signature Utils.Print(f"Retrying {cmd} due to: tx_cpu_usage_exceeded") continue # try again return (False, msg) + except subprocess.TimeoutExpired as ex: + if not silentErrors: + end=time.perf_counter() + Utils.Print("ERROR: Timeout during push message. retry %s. cmd timeout=%s. cmd Duration=%.3f sec." % + (retries, ex.timeout, end - start)) + return (False, ex) def setPermission(self, account, code, pType, requirement, waitForTransBlock=False, exitOnError=False, sign=False): assert(isinstance(account, Account)) From 42cb3031adf3b297ec76b45a993a4b3a9199786c Mon Sep 17 00:00:00 2001 From: Huang-Ming Huang Date: Tue, 9 Jun 2026 11:31:31 -0500 Subject: [PATCH 3/4] Address trace polling review feedback --- tests/TestHarness/queries.py | 37 ++++++++++++++++++++++++------- tests/TestHarness/testUtils.py | 20 ++++++++++++++--- tests/TestHarness/transactions.py | 12 ++++++---- 3 files changed, 54 insertions(+), 15 deletions(-) diff --git a/tests/TestHarness/queries.py b/tests/TestHarness/queries.py index c7edca9dda..cefb35961e 100644 --- a/tests/TestHarness/queries.py +++ b/tests/TestHarness/queries.py @@ -243,20 +243,37 @@ def getTransaction(self, transId, silentErrors=False, exitOnError=False, delayed """Fetch a transaction trace, bounding each poll so missing traces cannot stall bootstrap.""" assert(isinstance(transId, str)) exitOnErrorForDelayed=not delayedRetry and exitOnError - timeout=3 + pollTimeout=3 + pollBudget=60 + pollDeadline=time.perf_counter() + pollBudget cmdDesc="get transaction_trace" cmd="%s %s" % (cmdDesc, transId) - msg="(transaction id=%s)" % (transId); - for i in range(0,(int(60/timeout) - 1)): - trans=self.processClioCmd(cmd, cmdDesc, silentErrors=True, exitOnError=exitOnErrorForDelayed, exitMsg=msg, timeout=timeout) + msg="(transaction id=%s)" % (transId) + while True: + remainingBudget=pollDeadline - time.perf_counter() + if remainingBudget <= 0: + break + finalAttempt=remainingBudget <= pollTimeout + timeout=min(pollTimeout, remainingBudget) + attemptStart=time.perf_counter() + trans=self.processClioCmd(cmd, cmdDesc, + silentErrors=silentErrors if finalAttempt else True, + exitOnError=exitOnError if finalAttempt else exitOnErrorForDelayed, + exitMsg=msg, timeout=timeout) if trans is not None or not delayedRetry: return trans + if finalAttempt: + break + remainingBudget=pollDeadline - time.perf_counter() + if remainingBudget <= 0: + break if Utils.Debug: Utils.Print("Could not find transaction with id %s, delay and retry" % (transId)) - time.sleep(timeout) + attemptElapsed=time.perf_counter() - attemptStart + time.sleep(min(max(0, pollTimeout - attemptElapsed), remainingBudget)) self.missingTransaction=True # either it is there or the transaction has timed out - return self.processClioCmd(cmd, cmdDesc, silentErrors=silentErrors, exitOnError=exitOnError, exitMsg=msg, timeout=timeout) + return None def isTransInBlock(self, transId, blockId, exitOnError=False): """Check if transId is within block identified by blockId""" @@ -576,6 +593,7 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi start=time.perf_counter() while retries > 0: retries -= 1 + attemptStart=time.perf_counter() try: if returnType==ReturnType.json: trans=Utils.runCmdReturnJson(cmd, silentErrors=silentErrors, timeout=timeout) @@ -586,7 +604,7 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi if Utils.Debug: end=time.perf_counter() - Utils.Print("cmd Duration: %.3f sec" % (end-start)) + Utils.Print("cmd Duration: %.3f sec" % (end-attemptStart)) except subprocess.CalledProcessError as ex: if not silentErrors: end=time.perf_counter() @@ -605,7 +623,10 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi except subprocess.TimeoutExpired as ex: if not silentErrors: end=time.perf_counter() - errorMsg="Timeout during \"%s\" after %.3f sec. cmd timeout=%s. %s" % (cmdDesc, end-start, ex.timeout, exitMsg) + out=ex.output.decode("utf-8") if ex.output is not None else "" + msg=ex.stderr.decode("utf-8") if ex.stderr is not None else "" + errorMsg=("Timeout during \"%s\" after %.3f sec. cmd timeout=%s. stderr: %s. stdout: %s. %s" % + (cmdDesc, end-attemptStart, ex.timeout, msg, out, exitMsg)) if exitOnError: Utils.cmdError(errorMsg) Utils.errorExit(errorMsg) diff --git a/tests/TestHarness/testUtils.py b/tests/TestHarness/testUtils.py index 8d701a934e..d35476c128 100644 --- a/tests/TestHarness/testUtils.py +++ b/tests/TestHarness/testUtils.py @@ -222,7 +222,7 @@ def checkDelayedOutput(popen, cmd, ignoreError=False, timeout=None): popen.kill() (output,error)=popen.communicate() Utils.checkOutputFileWrite(start, cmd, output, error) - raise subprocess.TimeoutExpired(cmd=cmd, timeout=ex.timeout, output=output, stderr=error) + raise subprocess.TimeoutExpired(cmd=cmd, timeout=ex.timeout, output=output, stderr=error) from ex Utils.checkOutputFileWrite(start, cmd, output, error) if popen.returncode != 0 and not ignoreError: raise subprocess.CalledProcessError(returncode=popen.returncode, cmd=cmd, output=output, stderr=error) @@ -348,7 +348,8 @@ def runCmdReturnJson(cmd, trace=False, silentErrors=False, timeout=None): return Utils.runCmdArrReturnJson(cmdArr, trace=trace, silentErrors=silentErrors, timeout=timeout) @staticmethod - def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exitMsg=None): + def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exitMsg=None, timeout=None): + """Run sys-util and return stdout, optionally bounding the subprocess runtime.""" cmd="%s %s" % (Utils.SysioClientPath, cmd) if Utils.Debug: Utils.Print("cmd: %s" % (cmd)) if exitMsg is not None: @@ -358,7 +359,7 @@ def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exit output=None start=time.perf_counter() try: - output=Utils.runCmdReturnStr(cmd) + output=Utils.runCmdReturnStr(cmd, timeout=timeout) if Utils.Debug: end=time.perf_counter() @@ -374,6 +375,19 @@ def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exit else: Utils.Print("ERROR: %s" % (errorMsg)) return None + except subprocess.TimeoutExpired as ex: + if not silentErrors: + end=time.perf_counter() + out=ex.output.decode("utf-8") if ex.output is not None else "" + msg=ex.stderr.decode("utf-8") if ex.stderr is not None else "" + errorMsg=("Timeout during \"%s\" after %.3f sec. cmd timeout=%s. stderr: %s. stdout: %s. %s" % + (cmdDesc, end-start, ex.timeout, msg, out, exitMsg)) + if exitOnError: + Utils.cmdError(errorMsg) + Utils.errorExit(errorMsg) + else: + Utils.Print("ERROR: %s" % (errorMsg)) + return None if exitOnError and output is None: Utils.cmdError("could not \"%s\". %s" % (cmdDesc,exitMsg)) diff --git a/tests/TestHarness/transactions.py b/tests/TestHarness/transactions.py index 1934c8a400..62c1d569ec 100644 --- a/tests/TestHarness/transactions.py +++ b/tests/TestHarness/transactions.py @@ -12,7 +12,7 @@ class Transactions(NodeopQueries): retry_num_blocks_default = 1 - # Default clio action-push timeout, in seconds, used to keep intentionally interrupting transactions bounded. + # Default clio action-push subprocess timeout, in seconds, used to bound a stuck push. push_message_timeout_default = 45 def __init__(self, host, port, walletMgr=None): @@ -299,11 +299,15 @@ def pushMessage(self, account, action, data, opts, silentErrors=False, signature continue # try again return (False, msg) except subprocess.TimeoutExpired as ex: + msg=str(ex) + output=ex.output.decode("utf-8") if ex.output is not None else "" + error=ex.stderr.decode("utf-8") if ex.stderr is not None else "" if not silentErrors: end=time.perf_counter() - Utils.Print("ERROR: Timeout during push message. retry %s. cmd timeout=%s. cmd Duration=%.3f sec." % - (retries, ex.timeout, end - start)) - return (False, ex) + Utils.Print( + "ERROR: Timeout during push message. retry %s. cmd timeout=%s. stderr: %s. stdout: %s. cmd Duration=%.3f sec." % + (retries, ex.timeout, error, output, end - start)) + return (False, msg) def setPermission(self, account, code, pType, requirement, waitForTransBlock=False, exitOnError=False, sign=False): assert(isinstance(account, Account)) From d1990a1fa2b40ce213e93431075808276c4b2731 Mon Sep 17 00:00:00 2001 From: Huang-Ming Huang Date: Wed, 10 Jun 2026 17:32:50 +0000 Subject: [PATCH 4/4] Address transaction trace polling review comments --- tests/TestHarness/queries.py | 20 +++++++------------- tests/TestHarness/testUtils.py | 15 +++++++++++---- tests/TestHarness/transactions.py | 15 +++++++++------ 3 files changed, 27 insertions(+), 23 deletions(-) diff --git a/tests/TestHarness/queries.py b/tests/TestHarness/queries.py index cefb35961e..e3c74312ac 100644 --- a/tests/TestHarness/queries.py +++ b/tests/TestHarness/queries.py @@ -251,25 +251,19 @@ def getTransaction(self, transId, silentErrors=False, exitOnError=False, delayed msg="(transaction id=%s)" % (transId) while True: remainingBudget=pollDeadline - time.perf_counter() - if remainingBudget <= 0: - break finalAttempt=remainingBudget <= pollTimeout - timeout=min(pollTimeout, remainingBudget) attemptStart=time.perf_counter() trans=self.processClioCmd(cmd, cmdDesc, silentErrors=silentErrors if finalAttempt else True, exitOnError=exitOnError if finalAttempt else exitOnErrorForDelayed, - exitMsg=msg, timeout=timeout) + exitMsg=msg, timeout=pollTimeout) if trans is not None or not delayedRetry: return trans if finalAttempt: break - remainingBudget=pollDeadline - time.perf_counter() - if remainingBudget <= 0: - break if Utils.Debug: Utils.Print("Could not find transaction with id %s, delay and retry" % (transId)) attemptElapsed=time.perf_counter() - attemptStart - time.sleep(min(max(0, pollTimeout - attemptElapsed), remainingBudget)) + time.sleep(max(0, pollTimeout - attemptElapsed)) self.missingTransaction=True # either it is there or the transaction has timed out @@ -608,12 +602,12 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi except subprocess.CalledProcessError as ex: if not silentErrors: end=time.perf_counter() - out=ex.output.decode("utf-8") - msg=ex.stderr.decode("utf-8") + out=Utils.decodeProcessOutput(ex.output) + msg=Utils.decodeProcessOutput(ex.stderr) if retries > 0 and "tx_cpu_usage_exceeded" in out: Utils.Print(f"Retrying {cmdDesc} due to: tx_cpu_usage_exceeded") continue # try again - errorMsg="Exception during \"%s\". Exception message: %s. stdout: %s. cmd Duration=%.3f sec. %s" % (cmdDesc, msg, out, end-start, exitMsg) + errorMsg="Exception during \"%s\". Exception message: %s. stdout: %s. cmd Duration=%.3f sec. %s" % (cmdDesc, msg, out, end-attemptStart, exitMsg) if exitOnError: Utils.cmdError(errorMsg) Utils.errorExit(errorMsg) @@ -623,8 +617,8 @@ def processClioCmd(self, cmd, cmdDesc, silentErrors=True, exitOnError=False, exi except subprocess.TimeoutExpired as ex: if not silentErrors: end=time.perf_counter() - out=ex.output.decode("utf-8") if ex.output is not None else "" - msg=ex.stderr.decode("utf-8") if ex.stderr is not None else "" + out=Utils.decodeProcessOutput(ex.output) + msg=Utils.decodeProcessOutput(ex.stderr) errorMsg=("Timeout during \"%s\" after %.3f sec. cmd timeout=%s. stderr: %s. stdout: %s. %s" % (cmdDesc, end-attemptStart, ex.timeout, msg, out, exitMsg)) if exitOnError: diff --git a/tests/TestHarness/testUtils.py b/tests/TestHarness/testUtils.py index d35476c128..d56ede966b 100644 --- a/tests/TestHarness/testUtils.py +++ b/tests/TestHarness/testUtils.py @@ -199,6 +199,8 @@ def getChainStrategies(): @staticmethod def checkOutput(cmd, ignoreError=False, timeout=None): """Run a command and return stdout, optionally bounding the subprocess runtime.""" + assert timeout is None or isinstance(cmd, list), ( + "timeout with shell command strings can leave orphaned children") popen = Utils.delayedCheckOutput(cmd) return Utils.checkDelayedOutput(popen, cmd, ignoreError=ignoreError, timeout=timeout) @@ -226,7 +228,12 @@ def checkDelayedOutput(popen, cmd, ignoreError=False, timeout=None): Utils.checkOutputFileWrite(start, cmd, output, error) if popen.returncode != 0 and not ignoreError: raise subprocess.CalledProcessError(returncode=popen.returncode, cmd=cmd, output=output, stderr=error) - return output.decode("utf-8") if popen.returncode == 0 else error.decode("utf-8") + return Utils.decodeProcessOutput(output) if popen.returncode == 0 else Utils.decodeProcessOutput(error) + + @staticmethod + def decodeProcessOutput(output): + """Decode subprocess bytes without hiding diagnostics if a killed process wrote partial UTF-8.""" + return output.decode("utf-8", errors="replace") if output is not None else "" @staticmethod def errorExit(msg="", raw=False, errorCode=1): @@ -367,7 +374,7 @@ def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exit except subprocess.CalledProcessError as ex: if not silentErrors: end=time.perf_counter() - msg=ex.stderr.decode("utf-8") + msg=Utils.decodeProcessOutput(ex.stderr) errorMsg="Exception during \"%s\". Exception message: %s. cmd Duration=%.3f sec. %s" % (cmdDesc, msg, end-start, exitMsg) if exitOnError: Utils.cmdError(errorMsg) @@ -378,8 +385,8 @@ def processSysioUtilCmd(cmd, cmdDesc, silentErrors=True, exitOnError=False, exit except subprocess.TimeoutExpired as ex: if not silentErrors: end=time.perf_counter() - out=ex.output.decode("utf-8") if ex.output is not None else "" - msg=ex.stderr.decode("utf-8") if ex.stderr is not None else "" + out=Utils.decodeProcessOutput(ex.output) + msg=Utils.decodeProcessOutput(ex.stderr) errorMsg=("Timeout during \"%s\" after %.3f sec. cmd timeout=%s. stderr: %s. stdout: %s. %s" % (cmdDesc, end-start, ex.timeout, msg, out, exitMsg)) if exitOnError: diff --git a/tests/TestHarness/transactions.py b/tests/TestHarness/transactions.py index 62c1d569ec..b2cd3b55a2 100644 --- a/tests/TestHarness/transactions.py +++ b/tests/TestHarness/transactions.py @@ -123,7 +123,7 @@ def transferFunds(self, source, destination, amountStr, memo="memo", waitForTran self.trackCmdTransaction(trans, reportStatus=reportStatus) except subprocess.CalledProcessError as ex: end=time.perf_counter() - msg=ex.stderr.decode("utf-8") + msg=Utils.decodeProcessOutput(ex.stderr) Utils.Print("ERROR: Exception during funds transfer. cmd Duration: %.3f sec. %s" % (end-start, msg)) if exitOnError: Utils.cmdError("could not transfer \"%s\" from %s to %s" % (amountStr, source, destination)) @@ -264,8 +264,10 @@ def pushTransaction(self, trans, opts="", silentErrors=False, permissions=None): # returns tuple with transaction execution status and transaction def pushMessage(self, account, action, data, opts, silentErrors=False, signatures=None, expectTrxTrace=True, - timeout=push_message_timeout_default): + timeout=None): """Push an action with clio, bounding the clio subprocess runtime by default.""" + if timeout is None: + timeout = self.push_message_timeout_default cmd="%s %s push action -j %s %s" % (Utils.SysClientPath, self.sysClientArgs(), account, action) cmdArr=cmd.split() # not using sign_str, since cmdArr messes up the string @@ -289,8 +291,8 @@ def pushMessage(self, account, action, data, opts, silentErrors=False, signature Utils.Print("cmd Duration: %.3f sec" % (end-start)) return (NodeopQueries.getTransStatus(trans) == 'executed' if expectTrxTrace else True, trans) except subprocess.CalledProcessError as ex: - msg=ex.stderr.decode("utf-8") - output=ex.output.decode("utf-8") + msg=Utils.decodeProcessOutput(ex.stderr) + output=Utils.decodeProcessOutput(ex.output) if not silentErrors: end=time.perf_counter() Utils.Print("ERROR: Exception during push message. retry %s. stderr: %s. stdout: %s. cmd Duration=%.3f sec." % (retries, msg, output, end - start)) @@ -300,13 +302,14 @@ def pushMessage(self, account, action, data, opts, silentErrors=False, signature return (False, msg) except subprocess.TimeoutExpired as ex: msg=str(ex) - output=ex.output.decode("utf-8") if ex.output is not None else "" - error=ex.stderr.decode("utf-8") if ex.stderr is not None else "" + output=Utils.decodeProcessOutput(ex.output) + error=Utils.decodeProcessOutput(ex.stderr) if not silentErrors: end=time.perf_counter() Utils.Print( "ERROR: Timeout during push message. retry %s. cmd timeout=%s. stderr: %s. stdout: %s. cmd Duration=%.3f sec." % (retries, ex.timeout, error, output, end - start)) + # The killed clio process may have already broadcast the transaction before timing out; do not retry. return (False, msg) def setPermission(self, account, code, pType, requirement, waitForTransBlock=False, exitOnError=False, sign=False):