diff --git a/build.gradle b/build.gradle index 12a0622db99..f91a3f50663 100644 --- a/build.gradle +++ b/build.gradle @@ -81,8 +81,9 @@ subprojects { } dependencies { - implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.25' - implementation group: 'org.slf4j', name: 'jcl-over-slf4j', version: '1.7.25' + implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.36' + implementation group: 'org.slf4j', name: 'jcl-over-slf4j', version: '1.7.36' + implementation group: 'org.slf4j', name: 'jul-to-slf4j', version: '1.7.36' implementation group: 'ch.qos.logback', name: 'logback-classic', version: '1.2.13' implementation "com.google.code.findbugs:jsr305:3.0.0" implementation group: 'org.springframework', name: 'spring-context', version: "${springVersion}" diff --git a/chainbase/src/main/java/org/tron/common/storage/leveldb/LevelDbDataSourceImpl.java b/chainbase/src/main/java/org/tron/common/storage/leveldb/LevelDbDataSourceImpl.java index c48800573e1..b816cb74f2d 100644 --- a/chainbase/src/main/java/org/tron/common/storage/leveldb/LevelDbDataSourceImpl.java +++ b/chainbase/src/main/java/org/tron/common/storage/leveldb/LevelDbDataSourceImpl.java @@ -20,7 +20,9 @@ import com.google.common.annotations.VisibleForTesting; import com.google.common.collect.Sets; import com.google.common.primitives.Bytes; +import java.io.File; import java.io.IOException; +import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; @@ -29,9 +31,14 @@ import java.util.Collections; import java.util.HashMap; import java.util.List; +import java.util.Locale; import java.util.Map; import java.util.Map.Entry; import java.util.Set; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; import java.util.concurrent.locks.ReadWriteLock; import java.util.concurrent.locks.ReentrantReadWriteLock; import java.util.stream.Collectors; @@ -45,6 +52,7 @@ import org.iq80.leveldb.ReadOptions; import org.iq80.leveldb.WriteBatch; import org.iq80.leveldb.WriteOptions; +import org.tron.common.es.ExecutorServiceManager; import org.tron.common.parameter.CommonParameter; import org.tron.common.storage.WriteOptionsWrapper; import org.tron.common.storage.metric.DbStat; @@ -61,6 +69,13 @@ public class LevelDbDataSourceImpl extends DbStat implements DbSourceInter, Iterable>, Instance { + /** First watchdog WARN fires this many seconds after factory.open() begins. */ + private static final long OPEN_WATCHDOG_INITIAL_DELAY_SEC = 60; + /** Subsequent watchdog WARN lines are emitted on this interval. */ + private static final long OPEN_WATCHDOG_PERIOD_SEC = 30; + /** Value of {@code Filename.currentFileName()}. */ + private static final String LEVELDB_CURRENT_FILE = "CURRENT"; + private String dataBaseName; private DB database; private volatile boolean alive; @@ -121,6 +136,15 @@ private void openDatabase(Options dbOptions) throws IOException { if (!Files.isSymbolicLink(dbPath.getParent())) { Files.createDirectories(dbPath.getParent()); } + final long openStartNs = System.nanoTime(); + final AtomicReference manifestInfo = new AtomicReference<>(); + ScheduledExecutorService watchdog = ExecutorServiceManager + .newSingleThreadScheduledExecutor("db-open-watchdog-" + dataBaseName, true); + ScheduledFuture watchdogTask = watchdog.scheduleAtFixedRate( + () -> logSlowOpen(dbPath, openStartNs, manifestInfo), + OPEN_WATCHDOG_INITIAL_DELAY_SEC, + OPEN_WATCHDOG_PERIOD_SEC, + TimeUnit.SECONDS); try { DbSourceInter.checkOrInitEngine(getEngine(), dbPath.toString(), TronError.ErrCode.LEVELDB_INIT); @@ -139,7 +163,55 @@ private void openDatabase(Options dbOptions) throws IOException { logger.error("Open Database {} failed", dataBaseName, e); } throw new TronError(e, TronError.ErrCode.LEVELDB_INIT); + } finally { + watchdogTask.cancel(false); + watchdog.shutdownNow(); + } + } + + /** + * Emits a WARN when factory.open() is still blocked — usually because the + * MANIFEST has grown large enough to make replay expensive. + */ + void logSlowOpen(Path dbPath, long startNs, AtomicReference manifestInfoCache) { + try { + long elapsedSec = TimeUnit.NANOSECONDS.toSeconds(System.nanoTime() - startNs); + String manifestInfo = manifestInfoCache.get(); + if (manifestInfo == null) { + manifestInfo = resolveManifestInfo(dbPath.toFile()); + manifestInfoCache.compareAndSet(null, manifestInfo); + } + logger.warn("DB {} open still in progress after {}s. path={}, {}. " + + "This startup will complete; to speed up future restarts, run " + + "`java -jar Toolkit.jar db archive -d {}` before the next startup " + + "to rebuild the MANIFEST (the tool requires an exclusive DB lock, " + + "so it cannot run while the node is up).", + dataBaseName, elapsedSec, dbPath, manifestInfo, parentPath); + } catch (Exception e) { + // Purely observational - never let the watchdog disrupt startup. + logger.debug("db-open-watchdog failure for {}: {}", dataBaseName, e.getMessage()); + } + } + + private static String resolveManifestInfo(File dbDir) { + File currentFile = new File(dbDir, LEVELDB_CURRENT_FILE); + String name = "none"; + long size = 0; + if (currentFile.isFile()) { + try { + name = new String(Files.readAllBytes(currentFile.toPath()), + StandardCharsets.UTF_8).trim(); + File manifest = new File(dbDir, name); + if (manifest.isFile()) { + size = manifest.length(); + } + } catch (IOException ignored) { + // Best-effort — keep defaults. A new DB won't hit the 60s threshold + // anyway, so reporting 0.00 MB here is the expected shape. + } } + return String.format(Locale.ROOT, "MANIFEST=%s (%.2f MB)", name, + size / 1024.0 / 1024.0); } public Path getDbPath() { diff --git a/chainbase/src/main/java/org/tron/common/storage/metric/DbStat.java b/chainbase/src/main/java/org/tron/common/storage/metric/DbStat.java index c7fecf2a351..eb0362ad2e9 100644 --- a/chainbase/src/main/java/org/tron/common/storage/metric/DbStat.java +++ b/chainbase/src/main/java/org/tron/common/storage/metric/DbStat.java @@ -17,7 +17,7 @@ protected void statProperty() { double size = Double.parseDouble(tmp[2]) * 1048576.0; Metrics.gaugeSet(MetricKeys.Gauge.DB_SST_LEVEL, files, getEngine(), getName(), level); Metrics.gaugeSet(MetricKeys.Gauge.DB_SIZE_BYTES, size, getEngine(), getName(), level); - logger.info("DB {}, level:{},files:{},size:{} M", + logger.debug("DB {}, level:{},files:{},size:{} M", getName(), level, files, size / 1048576.0); }); } catch (Exception e) { diff --git a/chainbase/src/main/java/org/tron/core/capsule/TransactionCapsule.java b/chainbase/src/main/java/org/tron/core/capsule/TransactionCapsule.java index b11c6b1e0a4..57ff44ed253 100755 --- a/chainbase/src/main/java/org/tron/core/capsule/TransactionCapsule.java +++ b/chainbase/src/main/java/org/tron/core/capsule/TransactionCapsule.java @@ -35,6 +35,7 @@ import java.util.List; import java.util.concurrent.ExecutorService; import java.util.concurrent.Future; +import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicInteger; import lombok.Getter; import lombok.Setter; @@ -94,6 +95,8 @@ public class TransactionCapsule implements ProtoCapsule { .newFixedThreadPool(esName, CommonParameter.getInstance() .getValidContractProtoThreadNum()); private static final String OWNER_ADDRESS = "ownerAddress_"; + // 2-6 ms in general, so we set 50 ms as the threshold for slow signature verification. + private static final long SLOW_SIG_VERIFY_MS = 50; private Transaction transaction; @Setter @@ -648,6 +651,7 @@ public boolean validatePubSignature(AccountStore accountStore, byte[] hash = getTransactionId().getBytes(); + long startNs = System.nanoTime(); try { if (!validateSignature(this.transaction, hash, accountStore, dynamicPropertiesStore)) { isVerified = false; @@ -656,12 +660,27 @@ public boolean validatePubSignature(AccountStore accountStore, } catch (SignatureException | PermissionException | SignatureFormatException e) { isVerified = false; throw new ValidateSignatureException(e.getMessage()); + } finally { + logSlowSigVerify(startNs); } isVerified = true; } return true; } + /** + * INFO-logs when a single signature verification exceeds + * {@link #SLOW_SIG_VERIFY_MS}. Package-private so it can be exercised from + * tests without forcing a real slow crypto path. + */ + void logSlowSigVerify(long startNs) { + long costMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs); + if (costMs > SLOW_SIG_VERIFY_MS) { + logger.info("slow verify: txId={}, sigCount={}, cost={} ms", + getTransactionId(), this.transaction.getSignatureCount(), costMs); + } + } + /** * validate signature */ diff --git a/common/src/main/java/org/tron/common/log/LogService.java b/common/src/main/java/org/tron/common/log/LogService.java index bce52001e92..249b80aa773 100644 --- a/common/src/main/java/org/tron/common/log/LogService.java +++ b/common/src/main/java/org/tron/common/log/LogService.java @@ -2,6 +2,8 @@ import ch.qos.logback.classic.LoggerContext; import ch.qos.logback.classic.joran.JoranConfigurator; +import ch.qos.logback.classic.jul.LevelChangePropagator; +import ch.qos.logback.classic.spi.LoggerContextListener; import ch.qos.logback.core.util.StatusPrinter; import java.io.File; import org.slf4j.LoggerFactory; @@ -12,18 +14,42 @@ public class LogService { public static void load(String path) { LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); try { - File file = new File(path); - if (!file.exists() || !file.isFile() || !file.canRead()) { - return; + // we must fail fast rather than silently fall back and mislead them into + // thinking their custom config is active. + if (path != null && !path.isEmpty()) { + File file = new File(path); + if (!file.exists() || !file.isFile() || !file.canRead()) { + throw new IllegalArgumentException( + "logback config is not a readable file: " + path); + } + JoranConfigurator configurator = new JoranConfigurator(); + configurator.setContext(lc); + lc.reset(); + configurator.doConfigure(file); } - JoranConfigurator configurator = new JoranConfigurator(); - configurator.setContext(lc); - lc.reset(); - configurator.doConfigure(file); + // Whether we loaded a custom config via --log-config or kept the classpath + // default, make sure Logback level changes are propagated back to JUL so + // gRPC loggers actually honor the levels declared in the XML. If + // the active config already registered a LevelChangePropagator we leave + // it alone. + ensureLevelChangePropagator(lc); } catch (Exception e) { throw new TronError(e, TronError.ErrCode.LOG_LOAD); } finally { StatusPrinter.printInCaseOfErrorsOrWarnings(lc); } } + + private static void ensureLevelChangePropagator(LoggerContext lc) { + for (LoggerContextListener listener : lc.getCopyOfListenerList()) { + if (listener instanceof LevelChangePropagator) { + return; + } + } + LevelChangePropagator propagator = new LevelChangePropagator(); + propagator.setContext(lc); + propagator.setResetJUL(true); + propagator.start(); + lc.addListener(propagator); + } } diff --git a/common/src/main/java/org/tron/common/parameter/CommonParameter.java b/common/src/main/java/org/tron/common/parameter/CommonParameter.java index a73158a718a..fe82250d013 100644 --- a/common/src/main/java/org/tron/common/parameter/CommonParameter.java +++ b/common/src/main/java/org/tron/common/parameter/CommonParameter.java @@ -8,6 +8,7 @@ import java.util.Set; import lombok.Getter; import lombok.Setter; +import org.slf4j.bridge.SLF4JBridgeHandler; import org.tron.common.args.GenesisBlock; import org.tron.common.config.DbBackupConfig; import org.tron.common.cron.CronExpression; @@ -23,6 +24,19 @@ public class CommonParameter { + // Install the JUL->SLF4J bridge early so that JUL log records emitted during + // static init of grpc classes (or from unit tests that don't invoke + // LogService.load()) still reach Logback. + // removeHandlersForRootLogger() strips JUL's default ConsoleHandler so the + // same record is not emitted twice (once by JUL's own console output and + // once via the bridge to Logback). + static { + SLF4JBridgeHandler.removeHandlersForRootLogger(); + if (!SLF4JBridgeHandler.isInstalled()) { + SLF4JBridgeHandler.install(); + } + } + protected static CommonParameter PARAMETER = new CommonParameter(); // Runtime chain state: set by VMConfig.initVmHardFork() diff --git a/framework/src/main/java/org/tron/core/config/TronLogShutdownHook.java b/framework/src/main/java/org/tron/core/config/TronLogShutdownHook.java index f497b9a85d8..4ee8d58483c 100644 --- a/framework/src/main/java/org/tron/core/config/TronLogShutdownHook.java +++ b/framework/src/main/java/org/tron/core/config/TronLogShutdownHook.java @@ -2,7 +2,6 @@ import ch.qos.logback.core.hook.ShutdownHookBase; import ch.qos.logback.core.util.Duration; -import org.tron.program.FullNode; /** * @author kiven @@ -16,11 +15,24 @@ public class TronLogShutdownHook extends ShutdownHookBase { private static final Duration CHECK_SHUTDOWN_DELAY = Duration.buildByMilliseconds(100); /** - * The check times before shutdown. default is 60000/100 = 600 times. + * Maximum time to wait for a graceful application shutdown before forcing + * a log flush. Each pool managed by ExecutorServiceManager.shutdownAndAwait- + * Termination() can take up to 120 s in the worst case (60 s await + + * shutdownNow + 60 s await). 180 s is therefore not a hard upper bound, but + * a pragmatic headroom that assumes the many pools in the node shut down + * largely in parallel; in pathological cases trailing shutdown logs may + * still be truncated. In practice 180 s of shutdown output is also enough + * to diagnose most stalls — if a pool is still alive past that window the + * earlier logs already carry the stack/trace context needed to locate the + * offender, so truncating the tail is an acceptable trade-off against + * holding JVM exit open indefinitely. */ - private final long check_times = 60 * 1000 / CHECK_SHUTDOWN_DELAY.getMilliseconds(); + private static final long MAX_WAIT_MS = 3 * 60 * 1000; - // if true, shutdown hook will be executed , for example, 'java -jar FullNode.jar -[v|h]'. + private static final long CHECK_TIMES = + MAX_WAIT_MS / CHECK_SHUTDOWN_DELAY.getMilliseconds(); + + // if true, shutdown hook will be executed, for example, 'java -jar FullNode.jar -[v|h]'. public static volatile boolean shutDown = true; public TronLogShutdownHook() { @@ -29,16 +41,19 @@ public TronLogShutdownHook() { @Override public void run() { try { - for (int i = 0; i < check_times; i++) { + for (long i = 0; i < CHECK_TIMES; i++) { if (shutDown) { break; } - addInfo("Sleeping for " + CHECK_SHUTDOWN_DELAY); + if (i % 100 == 0) { + long elapsedSeconds = i * CHECK_SHUTDOWN_DELAY.getMilliseconds() / 1000; + addInfo("Waiting for application shutdown... elapsed=" + elapsedSeconds + "s"); + } Thread.sleep(CHECK_SHUTDOWN_DELAY.getMilliseconds()); } } catch (InterruptedException e) { Thread.currentThread().interrupt(); - addInfo("TronLogShutdownHook run error :" + e.getMessage()); + addInfo("TronLogShutdownHook interrupted: " + e.getMessage()); } super.stop(); } diff --git a/framework/src/main/resources/logback.xml b/framework/src/main/resources/logback.xml index 03d870e92e0..4f0099017c3 100644 --- a/framework/src/main/resources/logback.xml +++ b/framework/src/main/resources/logback.xml @@ -2,6 +2,14 @@ + + + true + + flush occurs often) --> 100 true + + 5000 - - - - - - - + + + diff --git a/framework/src/test/java/org/tron/common/log/LogServiceTest.java b/framework/src/test/java/org/tron/common/log/LogServiceTest.java new file mode 100644 index 00000000000..3ac00a9e599 --- /dev/null +++ b/framework/src/test/java/org/tron/common/log/LogServiceTest.java @@ -0,0 +1,138 @@ +package org.tron.common.log; + +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertThrows; + +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.jul.LevelChangePropagator; +import ch.qos.logback.classic.spi.LoggerContextListener; +import ch.qos.logback.classic.util.ContextInitializer; +import ch.qos.logback.core.joran.spi.JoranException; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.logging.Level; +import java.util.logging.Logger; +import org.junit.After; +import org.junit.Assert; +import org.junit.Rule; +import org.junit.Test; +import org.junit.rules.TemporaryFolder; +import org.slf4j.LoggerFactory; +import org.tron.core.exception.TronError; + +/** + * Verifies that {@link LogService#load(String)} keeps the Logback<->JUL level + * bridge working even when the active configuration does not declare a + * {@code LevelChangePropagator} itself. + */ +public class LogServiceTest { + + @Rule + public TemporaryFolder temporaryFolder = new TemporaryFolder(); + + @After + public void restoreDefaultLogbackConfig() { + LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); + lc.reset(); + try { + new ContextInitializer(lc).autoConfig(); + } catch (JoranException e) { + Assert.fail("failed to restore default logback config: " + e.getMessage()); + } + } + + @Test + public void propagatorIsInstalledWhenCustomConfigOmitsIt() throws IOException { + Path xml = writeLogbackXml("DEBUG", false); + + LogService.load(xml.toString()); + + LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); + assertEquals(1, countLevelChangePropagators(lc)); + + // LevelChangePropagator maps Logback DEBUG -> JUL FINE. + Level julLevel = Logger.getLogger("io.grpc").getLevel(); + assertNotNull("JUL level for io.grpc should be synced from Logback", julLevel); + assertEquals(Level.FINE, julLevel); + } + + @Test + public void propagatorIsNotDuplicatedWhenCustomConfigDeclaresIt() throws IOException { + Path xml = writeLogbackXml("INFO", true); + + LogService.load(xml.toString()); + + LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); + assertEquals("XML-declared propagator should not be duplicated", + 1, countLevelChangePropagators(lc)); + } + + @Test + public void propagatorIsEnsuredWhenNoLogConfigIsSupplied() { + LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory(); + // Drop whatever the default logback-test.xml registered so we can observe the + // fall-through path (no --log-config) installing the propagator on its own. + removeLevelChangePropagators(lc); + assertEquals(0, countLevelChangePropagators(lc)); + + // Empty path == no --log-config passed; must keep classpath default AND + // still install the propagator so JUL sync works. + LogService.load(""); + + assertEquals("ensureLevelChangePropagator should run on the default context", + 1, countLevelChangePropagators(lc)); + } + + @Test + public void nonEmptyInvalidPathFailsFast() { + // A non-empty --log-config that cannot be read must surface loudly instead + // of silently falling back to the classpath default. + TronError thrown = assertThrows(TronError.class, + () -> LogService.load("definitely-not-a-real-path.xml")); + assertEquals(TronError.ErrCode.LOG_LOAD, thrown.getErrCode()); + } + + private Path writeLogbackXml(String level, + boolean includePropagator) throws IOException { + StringBuilder sb = new StringBuilder(); + sb.append("\n"); + if (includePropagator) { + sb.append(" \n"); + sb.append(" true\n"); + sb.append(" \n"); + } + sb.append(" \n"); + sb.append(" %m%n\n"); + sb.append(" \n"); + sb.append(" \n"); + sb.append(" \n"); + sb.append("\n"); + Path path = temporaryFolder.newFile("logback.xml").toPath(); + Files.write(path, sb.toString().getBytes(StandardCharsets.UTF_8)); + return path; + } + + private static int countLevelChangePropagators(LoggerContext lc) { + int count = 0; + for (LoggerContextListener listener : lc.getCopyOfListenerList()) { + if (listener instanceof LevelChangePropagator) { + count++; + } + } + return count; + } + + private static void removeLevelChangePropagators(LoggerContext lc) { + for (LoggerContextListener listener : lc.getCopyOfListenerList()) { + if (listener instanceof LevelChangePropagator) { + lc.removeListener(listener); + } + } + } +} diff --git a/framework/src/test/java/org/tron/common/storage/leveldb/LevelDbDataSourceImplTest.java b/framework/src/test/java/org/tron/common/storage/leveldb/LevelDbDataSourceImplTest.java index 7fd792a958d..d8129bfa466 100644 --- a/framework/src/test/java/org/tron/common/storage/leveldb/LevelDbDataSourceImplTest.java +++ b/framework/src/test/java/org/tron/common/storage/leveldb/LevelDbDataSourceImplTest.java @@ -19,10 +19,23 @@ package org.tron.common.storage.leveldb; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; import static org.junit.Assert.assertThrows; +import static org.junit.Assert.assertTrue; +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; import java.io.File; import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.List; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicReference; +import java.util.stream.Collectors; import org.junit.AfterClass; import org.junit.Assert; import org.junit.Before; @@ -32,11 +45,13 @@ import org.junit.rules.ExpectedException; import org.junit.rules.TemporaryFolder; import org.rocksdb.RocksDB; +import org.slf4j.LoggerFactory; import org.tron.common.TestConstants; import org.tron.common.parameter.CommonParameter; import org.tron.common.storage.rocksdb.RocksDbDataSourceImpl; import org.tron.common.utils.FileUtil; import org.tron.common.utils.PropUtil; +import org.tron.common.utils.ReflectUtils; import org.tron.common.utils.StorageUtils; import org.tron.core.config.args.Args; import org.tron.core.exception.TronError; @@ -122,4 +137,68 @@ private void makeExceptionDb(String dbName) { FileUtil.saveData(dataSource.getDbPath().toString() + "/CURRENT", "...", Boolean.FALSE); } + + @Test + public void slowOpen() throws IOException { + Logger dbLogger = (Logger) LoggerFactory.getLogger("DB"); + ListAppender dbAppender = new ListAppender<>(); + dbAppender.start(); + dbLogger.addAppender(dbAppender); + try { + final File dbDir = temporaryFolder.newFolder(); + final Path dbPath = dbDir.toPath(); + final String manifest = "MANIFEST-000042"; + final String WATCHDOG_DB_NAME = "slow-open-db"; + Files.write(dbPath.resolve(manifest), new byte[1024 * 1024]); + Files.write(dbPath.resolve("CURRENT"), (manifest + "\n").getBytes(StandardCharsets.UTF_8)); + + LevelDbDataSourceImpl ds = new LevelDbDataSourceImpl(); + ReflectUtils.setFieldValue(ds, "dataBaseName", WATCHDOG_DB_NAME); + ReflectUtils.setFieldValue(ds, "parentPath", dbDir.getParent()); + long startNs = System.nanoTime() - TimeUnit.SECONDS.toNanos(61); + AtomicReference cache = new AtomicReference<>(); + ds.logSlowOpen(dbPath, startNs, cache); + + List warns = dbAppender.list.stream() + .filter(e -> e.getLevel() == Level.WARN) + .collect(Collectors.toList()); + assertEquals("expected exactly one WARN event", 1, warns.size()); + ILoggingEvent warn = warns.get(0); + assertNotNull("expected one WARN from the watchdog helper", warn); + String rendered = warn.getFormattedMessage(); + assertTrue("WARN should mention the MANIFEST filename: " + rendered, + rendered.contains(manifest)); + assertTrue("WARN should include MANIFEST size in MB: " + rendered, + rendered.contains("(1.00 MB)")); + assertTrue("WARN should include the Toolkit remediation hint: " + rendered, + rendered.contains("Toolkit.jar db archive -d")); + assertTrue("WARN should echo the db name: " + rendered, + rendered.contains(WATCHDOG_DB_NAME)); + assertNotNull("cache should hold the resolved MANIFEST info", cache.get()); + } finally { + dbAppender.stop(); + dbLogger.detachAppender(dbAppender); + } + } + + @Test + public void fastOpen() { + Logger dbLogger = (Logger) LoggerFactory.getLogger("DB"); + ListAppender dbAppender = new ListAppender<>(); + dbAppender.start(); + dbLogger.addAppender(dbAppender); + try { + String dir = Args.getInstance().getOutputDirectory() + + Args.getInstance().getStorage().getDbDirectory(); + LevelDbDataSourceImpl ds = new LevelDbDataSourceImpl(dir, "test_fast_open"); + ds.closeDB(); + long warnCount = dbAppender.list.stream() + .filter(e -> e.getLevel() == Level.WARN) + .count(); + assertEquals("no WARN should fire for a fast open", 0, warnCount); + } finally { + dbAppender.stop(); + dbLogger.detachAppender(dbAppender); + } + } } diff --git a/framework/src/test/java/org/tron/core/capsule/TransactionCapsuleTest.java b/framework/src/test/java/org/tron/core/capsule/TransactionCapsuleTest.java index 70434430262..cd247c24d2e 100644 --- a/framework/src/test/java/org/tron/core/capsule/TransactionCapsuleTest.java +++ b/framework/src/test/java/org/tron/core/capsule/TransactionCapsuleTest.java @@ -4,12 +4,20 @@ import static org.tron.protos.Protocol.Transaction.Result.contractResult.PRECOMPILED_CONTRACT; import static org.tron.protos.Protocol.Transaction.Result.contractResult.SUCCESS; +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; import com.google.protobuf.ByteString; +import java.util.List; +import java.util.concurrent.TimeUnit; +import java.util.stream.Collectors; import lombok.extern.slf4j.Slf4j; import org.junit.Assert; import org.junit.Before; import org.junit.BeforeClass; import org.junit.Test; +import org.slf4j.LoggerFactory; import org.tron.common.BaseTest; import org.tron.common.TestConstants; import org.tron.common.utils.StringUtil; @@ -69,4 +77,61 @@ public void testRemoveRedundantRet() { Assert.assertEquals(1, transactionCapsule.getInstance().getRetCount()); Assert.assertEquals(SUCCESS, transactionCapsule.getInstance().getRet(0).getContractRet()); } + + @Test + public void slowVerify() { + Logger capsuleLogger = (Logger) LoggerFactory.getLogger("capsule"); + Level originalLevel = capsuleLogger.getLevel(); + capsuleLogger.setLevel(Level.INFO); + ListAppender appender = new ListAppender<>(); + appender.start(); + capsuleLogger.addAppender(appender); + try { + TransactionCapsule cap = new TransactionCapsule(Transaction.newBuilder().build()); + long startNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(51); + cap.logSlowSigVerify(startNs); + + List infos = appender.list.stream() + .filter(e -> e.getLevel() == Level.INFO) + .collect(Collectors.toList()); + Assert.assertEquals("expected one INFO for a slow verify", 1, infos.size()); + String rendered = infos.get(0).getFormattedMessage(); + Assert.assertTrue("INFO should mention slow verify: " + rendered, + rendered.contains("slow verify")); + Assert.assertTrue("INFO should echo the txId: " + rendered, + rendered.contains(cap.getTransactionId().toString())); + Assert.assertTrue("INFO should include sigCount: " + rendered, + rendered.contains("sigCount=")); + Assert.assertTrue("INFO should include cost in ms: " + rendered, + rendered.contains("cost=")); + Assert.assertTrue("INFO should render ms suffix: " + rendered, + rendered.contains(" ms")); + } finally { + appender.stop(); + capsuleLogger.detachAppender(appender); + capsuleLogger.setLevel(originalLevel); + } + } + + @Test + public void fastVerify() { + Logger capsuleLogger = (Logger) LoggerFactory.getLogger("capsule"); + Level originalLevel = capsuleLogger.getLevel(); + capsuleLogger.setLevel(Level.INFO); + ListAppender appender = new ListAppender<>(); + appender.start(); + capsuleLogger.addAppender(appender); + try { + TransactionCapsule cap = new TransactionCapsule(Transaction.newBuilder().build()); + cap.logSlowSigVerify(System.nanoTime()); + long infoCount = appender.list.stream() + .filter(e -> e.getLevel() == Level.INFO) + .count(); + Assert.assertEquals("no INFO should fire below the threshold", 0, infoCount); + } finally { + appender.stop(); + capsuleLogger.detachAppender(appender); + capsuleLogger.setLevel(originalLevel); + } + } } \ No newline at end of file diff --git a/framework/src/test/java/org/tron/core/config/TronLogShutdownHookTest.java b/framework/src/test/java/org/tron/core/config/TronLogShutdownHookTest.java new file mode 100644 index 00000000000..85ade6ba7fa --- /dev/null +++ b/framework/src/test/java/org/tron/core/config/TronLogShutdownHookTest.java @@ -0,0 +1,84 @@ +package org.tron.core.config; + +import static org.junit.Assert.assertFalse; +import static org.junit.Assert.assertTrue; + +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +public class TronLogShutdownHookTest { + + private boolean originalShutDown; + + @Before + public void saveShutDownFlag() { + originalShutDown = TronLogShutdownHook.shutDown; + } + + @After + public void restoreShutDownFlag() { + TronLogShutdownHook.shutDown = originalShutDown; + } + + @Test(timeout = 5_000) + public void returnsImmediatelyWhenAlreadyShutDown() { + TronLogShutdownHook.shutDown = true; + + TronLogShutdownHook hook = new TronLogShutdownHook(); + long startNs = System.nanoTime(); + hook.run(); + long elapsedMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs); + assertTrue("hook should exit fast when shutDown==true, elapsed=" + elapsedMs + "ms", + elapsedMs < 2_000); + } + + @Test(timeout = 10_000) + public void wakesUpWhenShutDownFlagFlips() throws InterruptedException { + TronLogShutdownHook.shutDown = false; + + TronLogShutdownHook hook = new TronLogShutdownHook(); + Thread runner = new Thread(hook, "shutdown-hook-test-runner"); + runner.setDaemon(true); + runner.start(); + + Thread.sleep(300); + long flipNs = System.nanoTime(); + TronLogShutdownHook.shutDown = true; + + runner.join(5_000); + long elapsedAfterFlipMs = + TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - flipNs); + + assertFalse("runner should have exited after flag flipped, still alive", + runner.isAlive()); + // The loop sleeps in 100 ms slices, so it should wake up well inside one + // slice's worth of jitter. 1 s is comfortable even on slow CI. + assertTrue("hook should return shortly after flag flip, elapsed=" + + elapsedAfterFlipMs + "ms", elapsedAfterFlipMs < 1_000); + } + + @Test(timeout = 10_000) + public void preservesInterruptStatusWhenInterrupted() throws InterruptedException { + TronLogShutdownHook.shutDown = false; + + TronLogShutdownHook hook = new TronLogShutdownHook(); + AtomicBoolean interruptedAfterRun = new AtomicBoolean(false); + Thread runner = new Thread(() -> { + hook.run(); + interruptedAfterRun.set(Thread.currentThread().isInterrupted()); + }, "shutdown-hook-test-interrupt"); + runner.setDaemon(true); + runner.start(); + + Thread.sleep(200); + runner.interrupt(); + + runner.join(5_000); + assertFalse("runner should have exited after interrupt", runner.isAlive()); + assertTrue("run() must re-assert interrupt status after catching " + + "InterruptedException", interruptedAfterRun.get()); + } +} diff --git a/framework/src/test/java/org/tron/core/exception/TronErrorTest.java b/framework/src/test/java/org/tron/core/exception/TronErrorTest.java index e965ae3fd60..179f5ce32de 100644 --- a/framework/src/test/java/org/tron/core/exception/TronErrorTest.java +++ b/framework/src/test/java/org/tron/core/exception/TronErrorTest.java @@ -93,7 +93,14 @@ public void LogLoadTest() throws IOException { LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); try { - LogService.load("non-existent.xml"); + // Empty path means no --log-config supplied: keep the classpath default. + LogService.load(""); + // Non-empty path pointing at a missing file must fail fast so operators + // don't silently run with the classpath default. + TronError missing = assertThrows(TronError.class, + () -> LogService.load("non-existent.xml")); + assertEquals(TronError.ErrCode.LOG_LOAD, missing.getErrCode()); + // Non-empty path pointing at an unparseable file must also surface. Path path = temporaryFolder.newFile("logback.xml").toPath(); TronError thrown = assertThrows(TronError.class, () -> LogService.load(path.toString())); assertEquals(TronError.ErrCode.LOG_LOAD, thrown.getErrCode()); diff --git a/framework/src/test/java/org/tron/keystore/CredentialsTest.java b/framework/src/test/java/org/tron/keystore/CredentialsTest.java index 3fe2ce02b63..8aabd887bb0 100644 --- a/framework/src/test/java/org/tron/keystore/CredentialsTest.java +++ b/framework/src/test/java/org/tron/keystore/CredentialsTest.java @@ -1,25 +1,36 @@ package org.tron.keystore; -import java.security.NoSuchAlgorithmException; -import java.security.SecureRandom; -import junit.framework.TestCase; -import lombok.extern.slf4j.Slf4j; +import org.junit.Assert; import org.junit.Test; -import org.springframework.util.Assert; -import org.tron.common.crypto.SignUtils; +import org.mockito.Mockito; +import org.tron.common.crypto.SignInterface; import org.tron.common.crypto.sm2.SM2; import org.tron.common.utils.ByteUtil; +import org.tron.common.utils.StringUtil; -@Slf4j -public class CredentialsTest extends TestCase { +public class CredentialsTest { + + private static final byte[] ADDRESS_1 = ByteUtil.hexToBytes( + "410102030405060708090a0b0c0d0e0f1011121314"); + private static final byte[] ADDRESS_2 = ByteUtil.hexToBytes( + "411415161718191a1b1c1d1e1f2021222324252627"); + + private SignInterface mockSignInterface(byte[] address) { + SignInterface signInterface = Mockito.mock(SignInterface.class); + Mockito.when(signInterface.getAddress()).thenReturn(address); + return signInterface; + } @Test - public void testCreate() throws NoSuchAlgorithmException { - Credentials credentials = Credentials.create(SignUtils.getGeneratedRandomSign( - SecureRandom.getInstance("NativePRNG"),true)); - Assert.hasText(credentials.getAddress(),"Credentials address create failed!"); - Assert.notNull(credentials.getSignInterface(), - "Credentials cryptoEngine create failed"); + public void testCreate() { + SignInterface signInterface = mockSignInterface(ADDRESS_1); + + Credentials credentials = Credentials.create(signInterface); + + Assert.assertEquals("Credentials address create failed!", + StringUtil.encode58Check(ADDRESS_1), credentials.getAddress()); + Assert.assertSame("Credentials cryptoEngine create failed", signInterface, + credentials.getSignInterface()); } @Test @@ -28,21 +39,43 @@ public void testCreateFromSM2() { Credentials.create(SM2.fromNodeId(ByteUtil.hexToBytes("fffffffffff" + "ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff" + "fffffffffffffffffffffffffffffffffffffff"))); + Assert.fail("Expected IllegalArgumentException"); } catch (Exception e) { - Assert.isInstanceOf(IllegalArgumentException.class, e); + Assert.assertTrue(e instanceof IllegalArgumentException); } } @Test - public void testEquals() throws NoSuchAlgorithmException { - Credentials credentials1 = Credentials.create(SignUtils.getGeneratedRandomSign( - SecureRandom.getInstance("NativePRNG"),true)); - Credentials credentials2 = Credentials.create(SignUtils.getGeneratedRandomSign( - SecureRandom.getInstance("NativePRNG"),true)); - Assert.isTrue(!credentials1.equals(credentials2), - "Credentials instance should be not equal!"); - Assert.isTrue(!(credentials1.hashCode() == credentials2.hashCode()), - "Credentials instance hashcode should be not equal!"); + public void testEquals() { + Credentials credentials1 = Credentials.create(mockSignInterface(ADDRESS_1)); + Credentials credentials2 = Credentials.create(mockSignInterface(ADDRESS_2)); + + Assert.assertNotEquals("Credentials address fixtures should differ", + credentials1.getAddress(), credentials2.getAddress()); + Assert.assertNotEquals("Credentials instance should be not equal!", + credentials1, credentials2); + } + + @Test + public void testEqualsWithAddressAndCryptoEngine() { + Object aObject = new Object(); + SignInterface signInterface = mockSignInterface(ADDRESS_1); + SignInterface signInterface2 = mockSignInterface(ADDRESS_1); + SignInterface signInterface3 = mockSignInterface(ADDRESS_2); + + Credentials credential = Credentials.create(signInterface); + Credentials sameCredential = Credentials.create(signInterface); + Credentials sameAddressDifferentEngineCredential = Credentials.create(signInterface2); + Credentials differentCredential = Credentials.create(signInterface3); + + Assert.assertFalse(aObject.equals(credential)); + Assert.assertFalse(credential.equals(aObject)); + Assert.assertFalse(credential.equals(null)); + Assert.assertEquals(credential, sameCredential); + Assert.assertEquals("Equal credentials must have the same hashCode", + credential.hashCode(), sameCredential.hashCode()); + Assert.assertNotEquals(credential, sameAddressDifferentEngineCredential); + Assert.assertFalse(credential.equals(differentCredential)); } -} \ No newline at end of file +} diff --git a/framework/src/test/java/org/tron/keystroe/CredentialsTest.java b/framework/src/test/java/org/tron/keystroe/CredentialsTest.java deleted file mode 100644 index 2642129e00a..00000000000 --- a/framework/src/test/java/org/tron/keystroe/CredentialsTest.java +++ /dev/null @@ -1,33 +0,0 @@ -package org.tron.keystroe; - -import org.junit.Assert; -import org.junit.Test; -import org.mockito.Mockito; -import org.tron.common.crypto.SignInterface; -import org.tron.keystore.Credentials; - -public class CredentialsTest { - - @Test - public void test_equality() { - Object aObject = new Object(); - SignInterface si = Mockito.mock(SignInterface.class); - SignInterface si2 = Mockito.mock(SignInterface.class); - SignInterface si3 = Mockito.mock(SignInterface.class); - byte[] address = "TQhZ7W1RudxFdzJMw6FvMnujPxrS6sFfmj".getBytes(); - byte[] address2 = "TNCmcTdyrYKMtmE1KU2itzeCX76jGm5Not".getBytes(); - Mockito.when(si.getAddress()).thenReturn(address); - Mockito.when(si2.getAddress()).thenReturn(address); - Mockito.when(si3.getAddress()).thenReturn(address2); - Credentials aCredential = Credentials.create(si); - Assert.assertFalse(aObject.equals(aCredential)); - Assert.assertFalse(aCredential.equals(aObject)); - Assert.assertFalse(aCredential.equals(null)); - Credentials anotherCredential = Credentials.create(si); - Assert.assertTrue(aCredential.equals(anotherCredential)); - Credentials aCredential2 = Credentials.create(si2); - Assert.assertTrue(aCredential.equals(anotherCredential)); - Credentials aCredential3 = Credentials.create(si3); - Assert.assertFalse(aCredential.equals(aCredential3)); - } -} diff --git a/framework/src/test/resources/logback-test.xml b/framework/src/test/resources/logback-test.xml index cc8c84e831f..54462a6761d 100644 --- a/framework/src/test/resources/logback-test.xml +++ b/framework/src/test/resources/logback-test.xml @@ -1,5 +1,9 @@ + + true + + @@ -31,12 +35,13 @@ - + + diff --git a/gradle/verification-metadata.xml b/gradle/verification-metadata.xml index 86880157f35..29f510ef2e7 100644 --- a/gradle/verification-metadata.xml +++ b/gradle/verification-metadata.xml @@ -2221,12 +2221,20 @@ - - - + + + - - + + + + + + + + + + @@ -2255,21 +2263,6 @@ - - - - - - - - - - - - - - -