Issue with logs being stopped getting generated at midnight while using date based rollover strategy in log4j2

[snaralasetty]

Description

We are using log4j2 for logging in Sterling OMS product and observe that for 2 app servers, sometimes logging stops getting generated at midnight . Date based rollover strategy is implemented

Configuration

<RollingFile name="LULU_LOG_APPENDER" fileName="/opt/ssfs/runtime/logs/${sys:server_name:-}.log" filePattern="/opt/ssfs/runtime/logs/${sys:server_name:-}.log.%d{yyyy-MM-dd}">
        <PatternLayout pattern="%d:%-7p:%t: %-60m [%X{AppUserId}]: [%X{TenantId}]: %-25c{1}%n" />
	<Filters>
                    <SCILog4j2PatternFilter/>
            </Filters>
	<Policies>
		<TimeBasedTriggeringPolicy interval="1"/>
	</Policies> 
     </RollingFile>
	
     <RollingFile name="ALL" fileName="/opt/ssfs/runtime/logs/${sys:server_name:-}.log" filePattern="/opt/ssfs/runtime/logs/${sys:server_name:-}.log.%d{yyyy-MM-dd}">
        <PatternLayout pattern="%d:%-7p:%t: %-60m [%X{AppUserId}]: [%X{TenantId}]: %-25c{1}%n" />
	<Filters>
                    <SCILog4j2PatternFilter/>
            </Filters>
	<Policies>
		<TimeBasedTriggeringPolicy interval="1"/>
	</Policies> 
     </RollingFile>

Version: Log4J2

**Operating system: Unix (Sterling OMS v 10)

[snaralasetty]

Anyone who can help on this?

[vy]

Do you still observe this issue with the most recent Log4j version, that is, 2.22.1?

sometimes logging stops getting generated at midnight

• Mind elaborating on this please?
• Do you see any Log4j-generated logs on the issue? (They might be dumped to the console.)
• Does /opt/ssfs/runtime/logs/${sys:server_name:-}.log continue getting populated by logs after midnight?

[snaralasetty]

Hi vy,

1. Yes, it is using 2.22.1 log4j version

The issue is that we sometimes see that at log rollover (every day at 00:00 logs get rolled over to new file), logs don't get written to the new file 2) If you mean application logs, we don't see any log4h generated logs 3) Yes, we still see /opt/ssfs/runtime/logs/${sys:server_name:-}.log getting populated but our info level logs don't get written anymore to the log file post midnight

Note: This happens some days and doesn't happen on other days

[ppkarwasz]

What do the /opt/ssfs/runtime/logs/${sys:server_name:-}.log files contain? The TimeBasedTriggeringPolicy only triggers a rollover as a response to a log event, so they should not be empty.

Do you have enough free space on your filesystem?

[snaralasetty]

Yes, We don't see any issues with free space.

The logs during rollover on the day which it stopped generating are below (masked ipaddress)

####<Dec 12, 2023 11:59:58,875 PM PST> <Info> <WorkManager> <IPAddr> <oms_server18> <Timer-2> <<WLS Kernel>> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-0000000c> <1702454398875> <[severity-value: 64] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-002959> <Self-tuning thread pool contains 0 running threads, 3 idle threads, and 14 standby threads> ####<Dec 13, 2023 12:00:48,561 AM PST> <Info> <Diagnostics> <IPAddr> <oms_server18> <[ACTIVE] ExecuteThread: '10' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-000005c3> <1702454448561> <[severity-value: 64] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-320143> <Scheduled 1 data retirement tasks as per configuration.> ####<Dec 13, 2023 12:00:48,561 AM PST> <Info> <Diagnostics> <IPAddr> <oms_server18> <[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-000005c4> <1702454448561> <[severity-value: 64] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-320144> <Size based data retirement operation started on archive HarvestedDataArchive.> ####<Dec 13, 2023 12:00:50,307 AM PST> <Info> <Diagnostics> <IPAddr> <oms_server18> <[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-000005c4> <1702454450307> <[severity-value: 64] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-320145> <Size based data retirement operation completed on archive HarvestedDataArchive. Retired 1,980 records in 1,746 ms.> ####<Dec 13, 2023 12:00:50,309 AM PST> <Info> <Diagnostics> <IPAddr> <oms_server18> <[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-000005c4> <1702454450309> <[severity-value: 64] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-320144> <Size based data retirement operation started on archive EventsDataArchive.> ####<Dec 13, 2023 12:00:50,310 AM PST> <Info> <Diagnostics> <IPAddr> <oms_server18> <[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-000005c4> <1702454450310> <[severity-value: 64] [rid: 0] [partition-id: 0] [partition-name: DOMAIN] > <BEA-320145> <Size based data retirement operation completed on archive EventsDataArchive. Retired 0 records in 1 ms.> ####<Dec 13, 2023 12:00:58,830 AM PST> <Info> <Health> <IPAddr> <oms_server18> <weblogic.GCMonitor> <> <> <1479c544-6132-4300-a3fd-4284f7a22e0e-00000008> <1702454458830> <[severity-value: 64] [rid: 0:1] [partition-id: 0] [partition-name: DOMAIN] > <BEA-310002> <52% of the total memory in the server is free.>

[snaralasetty]

Any further update on this Piotr P. Karwasz?

[ppkarwasz]

@snaralasetty,

In the sample of your logs I can not find any message that matches the %d:%-7p:%t: %-60m [%X{AppUserId}]: [%X{TenantId}]: %-25c{1}%n pattern configured. Are you sure these are generated by Log4j Core?

If multiple logging backends are rotating the same files the results are unpredictable.

[snaralasetty]

On this question, we have two appenders configured to write in log files. LULU_LOG_APPENDER and ALL. Would this be the reason for this behavior?

[ppkarwasz]

Having two appenders logging to the same file is highly discouraged, but it could work (there should be a single RollingFileManager and one of the configurations will simply be ignored).

However if you have the same config on multiple web applications, it will fail and the logs of all but one application will be lost.

[github-actions[bot]]

This issue is stale because it has been waiting for your feedback for more than 60 days. The Apache Logging Services community values every submitted issue, but without additional information from you, we are unable to provide a solution to your problem. Please comment on this issue or it will be closed in 7 days.

[rgoers]

I would love to see what shows up with log4j2.debug=true set for the application during rollover. I don't think we actually have any tests for a configuration where two appenders will use the same rolling file manager. To be honest, since these are configured exactly the same I have no idea what the point of having two appenders is.

[github-actions[bot]]

This issue is stale because it has been waiting for your feedback for more than 60 days. The Apache Logging Services community values every submitted issue, but without additional information from you, we are unable to provide a solution to your problem. Please comment on this issue or it will be closed in 7 days.

[ppkarwasz]

There must be a bug in the Github Stale action. I'll check it out.

[github-actions[bot]]

This issue is stale because it has been waiting for your feedback for more than 60 days. The Apache Logging Services community values every submitted issue, but without additional information from you, we are unable to provide a solution to your problem. Please comment on this issue or it will be closed in 7 days.