Improve logging: SLF4J bridge, less startup noise, fix shutdown log loss

[halibobo1205]

Background

The current Java-tron logging and startup observability has five concrete problems that hurt operator diagnosis:

1. gRPC logs bypass Logback and go to stderr. grpc-java uses java.util.logging (JUL) internally. The project already ships jcl-over-slf4j, but the JUL→SLF4J bridge is absent. As a result, gRPC diagnostic messages — connection resets, TLS handshake failures, etc. — never reach tron.log, forcing operators to watch stderr and log files simultaneously (see grpc-java#1577).
2. DB stats flood startup at INFO. DbStat.statProperty() logs at INFO, burying critical initialization messages.
3. Shutdown logs are incomplete on abnormal exits. TronLogShutdownHook waits up to 180s after SIGTERM; if the node hangs inside that window, critical shutdown-phase logs may never be flushed.
4. Signature verification is invisible. ECDSA/SM2 signature recovery is a CPU hotspot. A single slow verification can stall block application or mempool admission, but today there is no per-call timing signal to locate it.
5. LevelDB startup silently blocks on an oversized MANIFEST. In LevelDbDataSourceImpl.openDatabase(), factory.open() is a JNI blocking call. When the MANIFEST file is large, the startup hangs there for minutes (or longer) with no log output. Operators cannot tell "stuck" from "recovering," and are not pointed at the Toolkit's DbArchive tool.

---

Core Changes

1. JUL→SLF4J bridge

At the earliest point during node startup (FullNode.main / SolidityNode.main), reset JUL's default handlers and install the bridge so gRPC's JUL output is routed through SLF4J/Logback:

// Remove default JUL handlers to avoid duplicate output
java.util.logging.LogManager.getLogManager().reset();
org.slf4j.bridge.SLF4JBridgeHandler.install();

// build.gradle
implementation 'org.slf4j:jul-to-slf4j:1.7.36'

2. Downgrade DB stats log level

Change log.info(...) in DbStat.statProperty() and similar periodic stat methods to log.debug(...), cutting startup noise without losing diagnostic value on demand.

3. Shutdown log completeness

Introduce a volatile boolean shuttingDown flag in TronLogShutdownHook, shorten unnecessary wait intervals, and make flushing critical log buffers the first-priority step in the JVM shutdown hook.

4. signature-verify INFO log

Instrument TransactionCapsule.validatePubSignature() around the validateSignature(Transaction, ...) call. When a single verification takes more than 10 ms, emit an INFO log with txId, signature count, permissionId, and elapsed ms:

long start = System.nanoTime();
try {
  if (!validateSignature(this.transaction, hash, accountStore, dynamicPropertiesStore)) {
    isVerified = false;
    throw new ValidateSignatureException("sig error");
  }
} finally {
  long costMs = (System.nanoTime() - start) / 1_000_000L;
  if (costMs > 50) {
    logger.info("slow sig verify: txId={}, sigCount={}, permissionId={}, cost={}ms",
        getTransactionId(), transaction.getSignatureCount(),
        transaction.getRawData().getContract(0).getPermissionId(), costMs);
  }
}

• The 50 ms threshold is a constant for now; it can be promoted to config later.
• Use nanoTime() to avoid millisecond-granularity sampling error.
• Covered hot paths: block application, mempool admission, P2P broadcast validation.

5. LevelDB startup watchdog

In LevelDbDataSourceImpl.openDatabase(), wrap the JNI-blocking factory.open(dbPath.toFile(), dbOptions) call with a watchdog:

• Before calling factory.open, submit a one-shot ScheduledExecutorService task. If factory.open has not returned within 60 s, emit the first WARN, then repeat every 30 s.

• WARN payload: dbName, dbPath, elapsed seconds, current MANIFEST filename and size (resolved by reading the CURRENT file to find the active MANIFEST, then File.length()).

• Each WARN includes a remediation hint:

  Database open is taking unusually long. If MANIFEST is oversized, run:
  java -jar Toolkit.jar db archive -d <database-directory>
  See DbArchive for details.

• Cancel the watchdog task as soon as factory.open returns, so no threads leak.

• The watchdog is purely observational: it does not change factory.open semantics or the startup flow.

---

Configuration Changes

• Add an explicit io.grpc logger entry in logback.xml so operators can tune gRPC log verbosity independently.
• DB stats loggers default to DEBUG; operators can promote them on demand.
• Slow-sig threshold (10 ms) and LevelDB watchdog timings (first WARN at 60 s, repeat every 30 s) ship as constants; whether to expose them as config will be decided based on feedback.

No API / Protocol Changes

No impact on external APIs or the network protocol.

---

Testing Strategy

1. gRPC bridge. Reproduce a TLS handshake failure or connection reset; verify the JUL-originated messages appear in tron.log and are no longer duplicated on stderr.
2. DB stats downgrade. Compare INFO-level line counts during startup before/after — expect a significant reduction and clearer initialisation output.
3. Shutdown completeness. SIGTERM followed by a deliberately stalled process; verify shutdown-phase logs are complete and flushed in time.
4. Slow-sig logging.
   • Unit test: craft a multi-sig transaction near totalSignNum; assert an INFO log fires when the cost exceeds 10 ms and does not fire below the threshold.
   • Load test: observe INFO frequency on a realistic workload; confirm it does not spam the log.
5. LevelDB watchdog.
   • Unit test: mock factory.open to block >60 s; assert the WARN payload includes dbName, MANIFEST size, and the remediation hint.
   • Fast-path test: on a normal fast open, assert the watchdog task is cancelled and no WARN is emitted.

---

Performance Considerations

• SLF4JBridgeHandler adds marginal overhead to JUL forwarding, but gRPC diagnostic logs are rare in normal operation — negligible impact.
• DB stats downgrade is pure log-I/O reduction, no runtime cost.
• Slow-sig instrumentation is two nanoTime() calls per verification — nanosecond-level overhead.
• The watchdog is a single scheduled task that exists only during startup; zero runtime cost afterwards.

Scope of Impact

Logging initialisation, DB stats log level, node shutdown lifecycle, transaction signature verification path, and LevelDB startup path.

Breaking Changes: None
Backward Compatibility: Fully compatible
Alternatives Considered: None

Caution

Note: The default log level for DB stats no longer messages has been adjusted. If you rely on these logs to analyze or monitor database disk usage, this information may no longer appear in the default logs after upgrading. Please adjust your log level configuration as needed, or use a more stable monitoring approach such as Prometheus metrics to collect database usage data.

---

References

• Solve logging grpc/grpc-java#1577
• SLF4J JUL Bridge
• DbArchive— Toolkit subcommand that rewrites oversized LevelDB MANIFEST files

[bladehan1]

Good idea. Incomplete or excessive log entries are common problems that affect daily use and should be fixed.

[halibobo1205]

Supplementing with POC evidence from the environment:
1. gRPC JUL logs leaking to stderr

Oct 16, 2025 3:31:59 AM io.grpc.netty.NettyServerTransport notifyTerminated
INFO: Transport failed
io.netty.handler.codec.http2.Http2Exception: HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: 0d0a

2. DB stats noise at startup (INFO level)

[2026-03-10T11:39:24.167Z] INFO  [db-stats] [metrics](DbStat.java:20) DB tmp, level:0,files:1.0,size:3.0 M
[2026-03-10T11:39:24.167Z] INFO  [db-stats] [metrics](DbStat.java:20) DB tmp, level:1,files:1.0,size:5.0 M
[2026-03-10T11:39:24.167Z] INFO  [db-stats] [metrics](DbStat.java:20) DB tmp, level:2,files:1.0,size:0.0 M
[2026-03-10T11:39:24.593Z] INFO  [db-stats] [metrics](DbStat.java:20) DB properties, level:0,files:3.0,size:4.0 M
[2026-03-10T11:39:24.593Z] INFO  [db-stats] [metrics](DbStat.java:20) DB properties, level:1,files:1.0,size:0.0 M
[2026-03-10T11:39:24.598Z] INFO  [db-stats] [metrics](DbStat.java:20) DB account, level:0,files:1.0,size:6.0 M
[2026-03-10T11:39:24.598Z] INFO  [db-stats] [metrics](DbStat.java:20) DB account, level:3,files:484.0,size:301.0 M
[2026-03-10T11:39:24.598Z] INFO  [db-stats] [metrics](DbStat.java:20) DB account, level:4,files:6758.0,size:10000.0 M
[2026-03-10T11:39:24.598Z] INFO  [db-stats] [metrics](DbStat.java:20) DB account, level:5,files:12786.0,size:22786.0 M
... (repeated across all DBs)

[halibobo1205]

Status Update
This has been added to v4.8.2 and is currently under development. Progress will be synced in this issue as it becomes available. Development is expected to be completed in early April.

[Murphytron]

@halibobo1205 , we've observed that some nodes get stuck during the initialization phase after upgrade, sometimes for more than 10 minutes without any log indication. It would be great if this could be improved or made more transparent as well.

[halibobo1205]

we've observed that some nodes get stuck during the initialization phase after upgrade, sometimes for more than 10 minutes without any log indication. It would be great if this could be improved or made more transparent as well.

Root cause

The hang you're observing is caused by LevelDB's MANIFEST file growing unboundedly during normal operation (a known upstream issue — leveldb#299, leveldb#899, leveldb#958). On restart, factory.open() must replay the entire MANIFEST log to rebuild the internal state. When the file reaches tens of gigabytes, this JNI call can block the Java thread for 10+ minutes with zero log output — because the blocking happens entirely inside native code before our success/error log is ever reached.

Existing mitigation

java-tron already ships a DbArchive tool (in the Toolkit.jar plugin) that rewrites the MANIFEST to a compact form by opening and immediately closing each LevelDB store. Running it before an upgrade can dramatically reduce startup time:

java -jar Toolkit.jar db archive -d /path/to/output-directory

Planned improvements

To make initialization more transparent, we plan to add the following to LevelDbDataSourceImpl.openDatabase():

Pre-open MANIFEST size log — check and log the MANIFEST file size before calling factory.open(), so operators can immediately tell whether a slow start is expected.
Watchdog thread — a daemon thread that emits a WARN log every 30 s while factory.open() is still blocking, including elapsed time and a pointer to DbArchive.
Open duration log — record how long factory.open() actually took, visible in the normal startup log.
These changes will be included in an upcoming release. In the meantime, running DbArchive before upgrading is the recommended workaround. @Murphytron

[lxcmyf]

Two questions seem worth pinning down here:

• Where is the earliest safe place to install the JUL -> SLF4J bridge? If it happens after parts of gRPC / Netty are already initialized, some startup-time diagnostics may still bypass tron.log, and if default JUL handlers are not reset carefully there is also a duplicate-log risk.
• For the recent "startup hangs with no logs" case, is that meant to be part of this issue too, or treated as a separate startup-transparency fix around LevelDbDataSourceImpl.openDatabase()? Feels related, but the implementation scope looks a bit different from the original logging cleanup.

[halibobo1205]

On question 1 — bridge installation timing

The bridge is installed in two places: the CommonParameter static initializer (covers unit tests which never call LogService.load(), runs before Spring context) and LogService.load() (reinstalled after Logback is fully configured, production path). removeHandlersForRootLogger() is called before each install to prevent duplicate output. LevelChangePropagator is also configured in logback.xml, so once Logback starts it propagates logger levels back into JUL, keeping both sides in sync. gRPC/Netty meaningful startup logs are emitted during Spring wiring, at which point both the bridge and the propagator are already in place — no startup diagnostics will be lost.

On question 2 — startup hang scope

We'd suggest keeping these as two separate PRs. This PR focuses on log routing. The LevelDB startup hang — JNI blocking silently on a large MANIFEST file — has a different root cause and implementation scope, and is better addressed in a follow-up PR. In the meantime, the DbArchive tool in Toolkit.jar can be used as a workaround. @lxcmyf cc @Murphytron

[halibobo1205]

The PR will be ready in a few days.