Add timestamps to management, server and agent .err logs - #12967
Conversation
|
This is a replacement for PR #12896 with the same .err timestamp change, but scoped to only the three log4j config files and based on the latest main. |
There was a problem hiding this comment.
Pull request overview
Note
Copilot was unable to run its full agentic suite in this review.
Updates Log4j2 console appender patterns to include timestamps so systemd-captured console/stderr .err logs are timestamped and aligned with existing rolling file logs (per #12887).
Changes:
- Prepended
%d{DEFAULT}to theCONSOLEappenderPatternLayoutin client, server, and agent configs. - Minor cleanup: removed a few blank/whitespace-only lines in the XML configs.
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
| server/conf/log4j-cloud.xml.in | Adds timestamp to console log pattern; minor whitespace cleanup. |
| client/conf/log4j-cloud.xml.in | Adds timestamp to console log pattern; minor whitespace cleanup. |
| agent/conf/log4j-cloud.xml.in | Adds timestamp to console log pattern; removes extra blank lines between logger entries. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
Codecov Report❌ Patch coverage is Additional details and impacted files@@ Coverage Diff @@
## main #12967 +/- ##
===========================================
Coverage 18.00% 18.01%
- Complexity 16464 16608 +144
===========================================
Files 5977 6029 +52
Lines 537726 542189 +4463
Branches 66026 66459 +433
===========================================
+ Hits 96839 97688 +849
- Misses 429968 433485 +3517
- Partials 10919 11016 +97
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 3 out of 3 changed files in this pull request and generated 3 comments.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| <Console name="CONSOLE" target="SYSTEM_OUT"> | ||
| <ThresholdFilter level="OFF" onMatch="ACCEPT" onMismatch="DENY"/> | ||
| <PatternLayout pattern="%-5p [%c{1.}] (%t:%x) %m%ex%n"/> | ||
| <PatternLayout pattern="%d{DEFAULT} %-5p [%c{1.}] (%t:%x) %m%ex%n"/> | ||
| </Console> |
There was a problem hiding this comment.
The PR description says the .err logs are fed from console/stderr, but this Console appender targets SYSTEM_OUT. If systemd is capturing stderr into .err, changing the stdout pattern won’t affect .err. Consider switching the console target to SYSTEM_ERR (or update the systemd unit routing) so the timestamped console output actually lands in .err.
|
@dheeraj12347 , can you check co-pilot’s comments and explain why it is not applicable (if so)? |
e953151 to
45c3bbe
Compare
|
Hi @DaanHoogland, This PR only updates the existing CONSOLE PatternLayout in the client, server, and agent log4j-cloud.xml.in files by prepending %d{DEFAULT}, so the console output captured in the .err files gets the same timestamped format as the rolling log files. I’m not changing the current console target or the service/unit stream routing here, since I wanted to keep this PR limited to the scope of issue #12887. I’ve also updated the PR description to remove the earlier “console/stderr” wording, which was confusing. Thanks for pointing it out :) |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 3 out of 3 changed files in this pull request and generated 1 comment.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| <Console name="CONSOLE" target="SYSTEM_OUT"> | ||
| <ThresholdFilter level="OFF" onMatch="ACCEPT" onMismatch="DENY"/> | ||
| <PatternLayout pattern="%-5p [%c{1.}] (%t:%x) %m%ex%n"/> | ||
| <PatternLayout pattern="%d{DEFAULT} %-5p [%c{1.}] (%t:%x) %m%ex%n"/> |
There was a problem hiding this comment.
I think we need to double check this, @dheeraj12347 . I looked in an env and the .out file already contains the date stamps for each line. The .err file doesn’t .
There was a problem hiding this comment.
I think we need to double check this, @dheeraj12347 . I looked in an env and the .out file already contains the date stamps for each line. The .err file doesn’t .
You’re right, Daan – .out already had timestamps while .err didn’t. I’ve now added a CONSOLE_ERR appender using SYSTEM_ERR with the same timestamped pattern, so stderr (and thus the .err files) will get timestamps as well.
|
@blueorangutan package |
|
@DaanHoogland a [SL] Jenkins job has been kicked to build packages. It will be bundled with no SystemVM templates. I'll keep you posted as I make progress. |
|
Packaging result [SF]: ✔️ el8 ✔️ el9 ✔️ el10 ✔️ debian ✔️ suse15. SL-JID 17465 |
|
@blueorangutan package |
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 3 out of 3 changed files in this pull request and generated 1 comment.
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
|
|
||
| <Console name="CONSOLE_ERR" target="SYSTEM_ERR"> | ||
| <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/> | ||
| <PatternLayout pattern="%d{DEFAULT} %-5p [%c{1.}] (%t:%x) %m%ex%n"/> |
There was a problem hiding this comment.
I’ve now updated usage/conf/log4j-cloud_usage.xml.in to add a CONSOLE_ERR appender targeting SYSTEM_ERR with a timestamped pattern, so usage.err will also get timestamps in line with issue #12887.
|
@blueorangutan package |
|
@DaanHoogland a [SL] Jenkins job has been kicked to build packages. It will be bundled with no SystemVM templates. I'll keep you posted as I make progress. |
boring-cyborg
Bot
added
Python
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 7 out of 7 changed files in this pull request and generated no new comments.
Suppressed comments (6)
services/console-proxy/server/src/main/java/com/cloud/consoleproxy/ConsoleProxy.java:86
sessionTimeoutMillisis stored in anintbut represents milliseconds; values above ~2,147,483,647 ms (~24.8 days) will overflow and can become negative, which would break both the WebSocket idle timeout and GC logic. Consider switching this to along(and parsing withLong.parseLong) and avoid exposing it as a public mutable static (e.g., make itprivate staticwith an accessor) to reduce accidental runtime modification.
/**
* Session timeout in milliseconds, default 300000 (5 minutes).
*/
public static int sessionTimeoutMillis = 300000;
services/console-proxy/server/src/main/java/com/cloud/consoleproxy/ConsoleProxy.java:180
sessionTimeoutMillisis stored in anintbut represents milliseconds; values above ~2,147,483,647 ms (~24.8 days) will overflow and can become negative, which would break both the WebSocket idle timeout and GC logic. Consider switching this to along(and parsing withLong.parseLong) and avoid exposing it as a public mutable static (e.g., make itprivate staticwith an accessor) to reduce accidental runtime modification.
// Read consoleproxy.session.timeout in milliseconds.
s = conf.getProperty("consoleproxy.session.timeout");
if (s != null) {
try {
int parsedTimeout = Integer.parseInt(s);
if (parsedTimeout < 1000) {
services/console-proxy/server/src/main/java/com/cloud/consoleproxy/ConsoleProxy.java:200
Class#newInstance()is deprecated and can mask constructor exceptions. Preferclz.getDeclaredConstructor().newInstance()so constructor failures are reported correctly and access checks are explicit.
try {
Class<?> clz = Class.forName(factoryClzName);
try {
ConsoleProxyServerFactory factory = (ConsoleProxyServerFactory) clz.newInstance();
factory.init(ConsoleProxy.ksBits, ConsoleProxy.ksPassword);
return factory;
services/console-proxy/server/src/main/java/com/cloud/consoleproxy/ConsoleProxyGCThread.java:72
File#delete()returns a boolean and does not throw under normal circumstances; thetry/catchwill rarely help and currently ignores delete failures whendelete()returnsfalse. Consider checking the boolean return value and logging when deletion fails (and optionally include the file path). Also, the updated log message lost a separating space after[ignored], reducing readability.
File logDir = new File("./logs");
File[] files = logDir.listFiles();
if (files != null) {
for (File file : files) {
if (System.currentTimeMillis() - file.lastModified() >= 86400000L) {
try {
file.delete();
} catch (Throwable e) {
logger.info("[ignored]failed to delete file: " + e.getLocalizedMessage());
}
services/console-proxy/server/src/main/java/com/cloud/consoleproxy/ConsoleProxyGCThread.java:54
- The timeout comparison truncates both configured milliseconds (
/ 1000) and observed idle time (/ 1000), which can effectively shorten the configured timeout by up to ~999ms and makes the behavior dependent on truncation boundaries. A more accurate approach is to compare using milliseconds (e.g., compute idleMillis and compare directly tosessionTimeoutMillis), or at least use a ceiling conversion when computing seconds from milliseconds to avoid disconnecting/GC’ing earlier than configured.
private int getMaxSessionIdleSeconds() {
if (ConsoleProxy.sessionTimeoutMillis <= 0) {
return DEFAULT_MAX_SESSION_IDLE_SECONDS;
}
return Math.max(1, ConsoleProxy.sessionTimeoutMillis / 1000);
}
services/console-proxy/server/src/main/java/com/cloud/consoleproxy/ConsoleProxyGCThread.java:103
- The timeout comparison truncates both configured milliseconds (
/ 1000) and observed idle time (/ 1000), which can effectively shorten the configured timeout by up to ~999ms and makes the behavior dependent on truncation boundaries. A more accurate approach is to compare using milliseconds (e.g., compute idleMillis and compare directly tosessionTimeoutMillis), or at least use a ceiling conversion when computing seconds from milliseconds to avoid disconnecting/GC’ing earlier than configured.
long secondsUnused = (System.currentTimeMillis() - client.getClientLastFrontEndActivityTime()) / 1000;
if (secondsUnused < getMaxSessionIdleSeconds()) {
|
Hi @DaanHoogland , thanks for the review and approval! Just wanted to check if there’s anything else needed from my side for this PR, particularly regarding the remaining testing/CI checks :) |
not coding wise, maybe find/lobby for some test- and review effort. |
kiranchavala
left a comment
kiranchavala
left a comment
There was a problem hiding this comment.
LGTM tested manually the following logs and the timestamp was present
tail -5 /var/log/cloudstack/management/management-server.err
2026-09-09 07:28:50,221 ERROR [o.a.c.n.t.s.TungstenServiceImpl] (qtp1151704483-16:[ctx-c73cbdc3, ctx-c00fee42]) (logid:f80f909e) Failed to find a Tungsten-Fabric provider
2026-09-09 07:28:56,194 ERROR [o.a.c.n.t.s.TungstenFabricUtils] (qtp1151704483-16:[ctx-2719bb77, ctx-c5ade299]) (logid:14812337) No Tungsten-Fabric provider have been found!
2026-09-09 07:28:56,194 ERROR [o.a.c.n.t.s.TungstenServiceImpl] (qtp1151704483-16:[ctx-2719bb77, ctx-c5ade299]) (logid:14812337) Failed to find a Tungsten-Fabric provider
2026-09-09 07:30:11,519 ERROR [o.a.c.s.i.TemplateServiceImpl] (qtp1151704483-16:[ctx-30c56d42, ctx-233e2212]) (logid:e374d010) No remote endpoint to send command, check if host or ssvm is down?
2026-09-09 07:30:11,729 ERROR [c.c.u.SystemVmTemplateRegistration] (qtp1151704483-16:[ctx-30c56d42, ctx-233e2212]) (logid:e374d010) Failed to delete temporary directory: /tmp/tmp5978824555832899862
tail -5 /var/log/cloudstack/management/management-server.out
2026-09-09 11:16:26,050 DEBUG [c.c.n.r.V.CheckRouterTask] (RouterStatusMonitor-1:[ctx-3728f9e0]) (logid:26754052) Found 1 routers to update status.
2026-09-09 11:16:26,051 DEBUG [c.c.n.r.V.CheckRouterTask] (RouterStatusMonitor-1:[ctx-3728f9e0]) (logid:26754052) Found 0 VPC's to update Redundant State.
2026-09-09 11:16:26,052 DEBUG [c.c.n.r.V.CheckRouterTask] (RouterStatusMonitor-1:[ctx-3728f9e0]) (logid:26754052) Found 0 networks to update RvR status.
2026-09-09 11:16:26,475 INFO [c.c.c.ClusterManagerImpl] (Cluster-Heartbeat-1:[ctx-8ae401ca]) (logid:dea68798) No inactive management server node found
2026-09-09 11:16:26,475 DEBUG [c.c.c.ClusterManagerImpl] (Cluster-Heartbeat-1:[ctx-8ae401ca]) (logid:dea68798) Peer scan is finished. profiler: Done. Duration: 2ms , profilerQueryActiveList: Done. Duration: 1ms, , profilerSyncClusterInfo: Done. Duration: 0ms, profilerInvalidatedNodeList: Done. Duration: 0ms, profilerRemovedList: Done. Duration: 0ms,, profilerNewList: Done. Duration: 0ms, profilerInactiveList: Done. Duration: 0ms
/var/log/cloudstack/usage/usage.err
11:26:02,288 ERROR UsageJobDaoImpl_EnhancerByCloudStack_b1f179d0:441 - DB Exception on: null java.sql.SQLTransientConnectionException: usage - Connection is not available, request timed out after 30002ms (total=0, active=0, idle=0, waiting=0)
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:714)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:184)
tail -f /var/log/cloudstack/usage/usage.out
11:26:23,296 INFO UsageJobDaoImpl_EnhancerByCloudStack_b1f179d0:220 - Found 1 opens job, to remove
11:26:23,297 DEBUG UsageJobDaoImpl_EnhancerByCloudStack_b1f179d0:222 - Removing job - id: 1, pid: 15160, job type: 0, scheduled: 0, heartbeat: 2026-09-09T11:25:02.000+0000
11:26:23,358 INFO ComponentContext:141 - Starting org.apache.cloudstack.quota.QuotaStatementImpl_EnhancerByCloudStack_e5fe0673
11:26:23,358 INFO QuotaStatementImpl_EnhancerByCloudStack_e5fe0673:101 - Starting Statement Manager
11:26:23,358 INFO ComponentContext:141 - Starting org.apache.cloudstack.quota.QuotaAlertManagerImpl_EnhancerByCloudStack_807a62af
11:26:23,358 INFO QuotaAlertManagerImpl_EnhancerByCloudStack_807a62af:134 - Starting Alert Manager
11:26:23,359 INFO ComponentContext:141 - Starting org.apache.cloudstack.quota.QuotaManagerImpl_EnhancerByCloudStack_c3215ae1
11:26:23,359 INFO QuotaManagerImpl_EnhancerByCloudStack_c3215ae1:132 - Starting Quota Manager
11:26:23,359 INFO ComponentContext:141 - Starting com.cloud.usage.UsageAlertManagerImpl_EnhancerByCloudStack_73fdac08
11:26:23,360 INFO UsageServer:61 - UsageServer ready...
kvm host
tail -f /var/log/cloudstack/agent/agent.out
2026-09-09 11:19:59,292 DEBUG [kvm.resource.LibvirtConnection] (AgentRequest-Handler-3:[]) (logid:d5122c54) Looking for libvirtd connection at: qemu:///system
2026-09-09 11:19:59,302 DEBUG [kvm.storage.LibvirtStorageAdaptor] (AgentRequest-Handler-3:[]) (logid:d5122c54) Successfully refreshed pool 207f29cc-05e8-3835-bbeb-71059f2b9ced Capacity: (3.9053 TB) 4293893554176 Used: (3.2545 TB) 3578409254912 Available: (666.35 GB) 715484299264
console proxy systemvm logs
root@v-1-VM:~# tail -f /var/log/cloud/cloud.out
2026-09-09T07:32:59,577 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property port: 8250
2026-09-09T07:32:59,579 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property name: v-1-VM
2026-09-09T07:32:59,581 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property guid: Proxy.1
2026-09-09T07:32:59,583 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property gateway: 10.0.48.1
2026-09-09T07:32:59,586 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting httpListenPort=80
2026-09-09T07:32:59,592 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting httpCmdListenPort=8001
2026-09-09T07:32:59,595 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting reconnectMaxRetry=5
2026-09-09T07:32:59,596 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting defaultBufferSize=65536
2026-09-09T07:32:59,604 INFO [cloud.consoleproxy.ConsoleProxyBaseServerFactoryImpl] (Console-Proxy-Main:[]) create HTTP server instance at port: 80
2026-09-09T07:33:00,076 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Listening for HTTP CMDs on port 8001
^C
root@v-1-VM:~# tail -f /var/log/cloud.log
2026-09-09T07:32:59,577 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property port: 8250
2026-09-09T07:32:59,579 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property name: v-1-VM
2026-09-09T07:32:59,581 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property guid: Proxy.1
2026-09-09T07:32:59,583 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Property gateway: 10.0.48.1
2026-09-09T07:32:59,586 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting httpListenPort=80
2026-09-09T07:32:59,592 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting httpCmdListenPort=8001
2026-09-09T07:32:59,595 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting reconnectMaxRetry=5
2026-09-09T07:32:59,596 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Setting defaultBufferSize=65536
2026-09-09T07:32:59,604 INFO [cloud.consoleproxy.ConsoleProxyBaseServerFactoryImpl] (Console-Proxy-Main:[]) create HTTP server instance at port: 80
2026-09-09T07:33:00,076 INFO [cloud.consoleproxy.ConsoleProxy] (Console-Proxy-Main:[]) Listening for HTTP CMDs on port 8001
This change updates console logging and stderr routing so .err files get timestamped entries for:
client/conf/log4j-cloud.xml.in
server/conf/log4j-cloud.xml.in
agent/conf/log4j-cloud.xml.in
usage/conf/log4j-cloud_usage.xml.in
For the management server, API server, and agents, the CONSOLE appender patterns now include %d{DEFAULT} at the beginning (matching the existing rolling file appender patterns), and a CONSOLE_ERR appender has been added that sends ERROR and above to SYSTEM_ERR with the same timestamped pattern. This ensures that the stderr output captured into the .err files by the systemd units includes timestamps and aligns more closely with the corresponding .log files.
For the Usage server, a CONSOLE_ERR appender targeting SYSTEM_ERR has been added using the existing %d{ABSOLUTE}{GMT} timestamp pattern, so usage.err also gets timestamped entries.
Hyper-V’s log4j-cloud.xml.in already uses a timestamped console pattern and is unchanged.
Fixes #12887.