Log entries just sporadically missing

[freakwave10]

Hi all,

inistially we had a console handler and a rotating file handler configured in our full configuration profile.

Due to performance issues I disabled the console handler.

Now we have this weird issue where sometimes the server just does not log stuff. And that is very randomly.

e.g. we have one job running every five minutes. And from the DB I see audit entries every 5 mintues. But the log looks like this:

2017-12-01 01:05:00,014 INFO   274665 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1039, open counter: -1039

2017-12-01 01:15:00,328 INFO   274729 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1040, open counter: -1040

2017-12-01 01:35:00,004 INFO   274670 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1041, open counter: -1041

2017-12-01 01:45:00,005 INFO   274744 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1042, open counter: -1042

2017-12-01 02:30:00,010 INFO   274632 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1043, open counter: -1043

2017-12-01 02:50:00,001 INFO   274737 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1044, open counter: -1044

2017-12-01 03:10:00,004 INFO   274570 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1045, open counter: -1045

2017-12-01 03:30:00,006 INFO   274660 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1046, open counter: -1046

2017-12-01 03:40:00,023 INFO   274802 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1047, open counter: -1047

2017-12-01 03:50:00,008 INFO   274807 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1048, open counter: -1048

2017-12-01 03:55:00,025 INFO   274811 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1049, open counter: -1049

2017-12-01 04:35:00,001 INFO   274771 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1050, open counter: -1050

2017-12-01 04:50:00,003 INFO   274797 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1051, open counter: -1051

2017-12-01 05:00:00,004 INFO   274780 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1052, open counter: -1052

2017-12-01 05:20:00,026 INFO   274687 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1053, open counter: -1053

2017-12-01 05:50:00,014 INFO   274844 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1054, open counter: -1054

2017-12-01 06:15:00,003 INFO   274834 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1055, open counter: -1055

2017-12-01 06:30:00,020 INFO   274814 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1056, open counter: -1056

2017-12-01 06:40:00,021 INFO   274774 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1057, open counter: -1057

2017-12-01 06:55:00,039 INFO   274677 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1058, open counter: -1058

2017-12-01 07:05:00,587 INFO   274876 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1059, open counter: -1059

2017-12-01 07:20:00,016 INFO   274898 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1060, open counter: -1060

2017-12-01 07:40:00,032 INFO   274863 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1061, open counter: -1061

2017-12-01 07:55:00,009 INFO   274653 [com.kona.ebsmoduleV1.jobs.EbsSynchUserJob] [execute] - --------EbsSynchUserJob Start JobName: EbsSynchUserJob, overall counter: 1062, open counter: -1062

You see just certain schedules are complete skipped. I see this in QA and in Production enviornment.

I am completely puzzeld by this. Any help would be very appreciated.

Enviornment is windows and:

Wildfly verion is 10.1.0.Final

  JAVA: "D:\Programs\Java\jdk1.8.0_91\bin\java"

  JAVA_OPTS: "-Dprogram.name=standalone.bat -Xms512M -Xmx2048M -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman"

Kind regards,

Wolfgang

[dmlloyd]

And yet your counter is perfectly sequential.  Are you certain that it is the logs that are missing?

[gir489]

This reminds me of the Silk Air 185 crash, where they thought the recorder was shut off by the pilot, but in fact, they found evidence that the recorder was switching itself off randomly due to a circuit fault.

Anyway, are you using Wildfly's Log4J module as a dependency? I had several issues with my project when porting it to Wildfly that were caused by using my own log4j.jar, and I'd imagine that something similar might be happening in your case. You could try using log4j as a META-INF dependency.

But as David mentioned, your counter is sequential, so there doesn't seem to be anything lost in the ether... This is very puzzling for sure.

[mohan525]

Is it a clustered environment or non-clustered? It happened to me in the past that some of the requests were directed to the node 2 in the cluster and I was expecting to see the log output in node 1.

[freakwave10]

I am so sorry, I could slap myself.

QA was pointing to prod DB ...