Log statements in Reader/Writer/Processor/Listener not printing

[tcesenthil]

I am trying to run a JSR352 java batch program in Java SE mode using JBERET implementation. I can see my main() method getting executed. It is in this main() method i get handle of a job operator and starting the job.

public static void main(String[] args) {

    LoggingConfig logConfiguration = new LoggingConfig();

    logger.info("Begining Batch with JBeret approach");

    JobOperator jo = BatchRuntime.getJobOperator();
    long id = jo.start("PilotJob", null);

    logger.info("End of Batch");

}

but, I do not see any log statements inside my reader, processor, writer or listeners getting printed.

I have a logging.properties defined and loaded from my projects src/main/resources/META-INF folder. The log statements in my main() method is getting printed according to it but, the log statements in my reader/writer/processor and listeners aren't printing at all.

public class LoggingConfig {
    public LoggingConfig() {
        try {
            // Load a properties file from class path that way can't be achieved
            // with java.util.logging.config.file

              final LogManager logManager = LogManager.getLogManager(); 
              try (final InputStream is = getClass().getResourceAsStream("/META-INF/logging.properties")) 
              {
                  logManager.readConfiguration(is);
              }

        } catch (Exception e) {
            System.out.println("Error while reading Log configuration file");
            e.printStackTrace();
        }
    }
}

Why isn't my log statements (java log library) in my java batch program to be printed ?

I have also tried giving the following VM Arguments while running my java program , yet no changes

-Dorg.jboss.logging.provider=jdk -Djava.util.logging.config.file=C:\pilotJBeret\src\main\resources\META-INF\logging.properties

Here are the logs from the main() method. I can clearly see that a job has been started but, not sure why the log statements of the batch program isn't getting printed.

    INFO: App Begining Batch with JBeret approach
    INFO: org.jboss.weld.Version WELD-000900: 2.2.15 (Final)
    INFO: org.jboss.weld.Bootstrap WELD-ENV-000014: Falling back to Java Reflection for bean-discovery-mode="annotated" discovery. Add org.jboss:jandex to the classpath to speed-up startup.
    INFO: org.jboss.weld.Bootstrap WELD-000101: Transactional services not available. Injection of @Inject UserTransaction not available. Transactional observers will be invoked synchronously.
    WARN: org.jboss.weld.Interceptor WELD-001700: Interceptor annotation class javax.ejb.PostActivate not found, interception based on it is not enabled
    WARN: org.jboss.weld.Interceptor WELD-001700: Interceptor annotation class javax.ejb.PrePassivate not found, interception based on it is not enabled
    DEBUG: org.jboss.weld.Bootstrap WELD-000100: Weld initialized. Validating beans
    DEBUG: org.jboss.weld.Reflection WELD-000620: interface javax.enterprise.inject.Intercepted is not declared @Target(METHOD, FIELD, PARAMETER, TYPE). Weld will use this annotation, however this may make the application unportable.
    DEBUG: org.jboss.weld.Reflection WELD-000620: interface javax.enterprise.inject.Decorated is not declared @Target(METHOD, FIELD, PARAMETER, TYPE). Weld will use this annotation, however this may make the application unportable.        
    FINE: javax.batch.runtime.BatchRuntime Loaded BatchContainerServiceProvider with className = org.jberet.operations.JobOperatorImpl
    TRACE: org.jberet JBERET000022: resume is not implemented for local transactions
    DEBUG: org.jberet JBERET000017: Persisted org.jberet.runtime.JobInstanceImpl@6 with id 6
    DEBUG: org.jberet JBERET000017: Persisted org.jberet.runtime.JobExecutionImpl@6 with id 6
    INFO: App End of Batch

[jamezp]

Are you using a java.uitl.logging.Logger in your reader/writer/processor?

[tcesenthil]

@jamezp yes

[tcesenthil]

i have also tried using System.out.println() within my Reader/Writer/Processor/Listeners. Even those messages are not getting printed.

[jamezp]

There shouldn't be anything consuming stdout or reconfiguring logging in JBeret itself. The JBeret test suite itself uses logging and writes to stdout with no issues.

What does your logging.properties look like? What kind of other dependencies do you have in your project?

[tcesenthil]

my logging.properties has the following content

.level=INFO
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.SimpleFormatter.format=%4$s: %3$s %5$s%n

my pom.xml dependencies are as follows

<dependencies>
		<dependency>
			<groupId>com.ibm</groupId>
			<artifactId>jzos</artifactId>
			<version>1</version>
			<!-- <scope>runtime</scope> -->
		</dependency>
		<dependency>
			<groupId>com.h2database</groupId>
			<artifactId>h2</artifactId>
			<version>1.4.188</version>
		</dependency>
		<dependency>
			<groupId>javax.batch</groupId>
			<artifactId>javax.batch-api</artifactId>
			<version>1.0.1</version>
			<scope>compile</scope>
		</dependency>
		<dependency>
			<groupId>javax.inject</groupId>
			<artifactId>javax.inject</artifactId>
			<version>1</version>
			<scope>compile</scope>
		</dependency>
		<dependency>
			<groupId>javax.transaction</groupId>
			<artifactId>jta</artifactId>
			<version>1.1</version>
			<scope>runtime</scope>
		</dependency>
		<dependency>
			<groupId>org.jberet</groupId>
			<artifactId>jberet-se</artifactId>
			<version>${jberet.version}</version>
		</dependency>
		<dependency>
			<groupId>org.jberet</groupId>
			<artifactId>jberet-support</artifactId>
			<version>${jberet.version}</version>
		</dependency>
		<dependency>
			<groupId>org.jboss.marshalling</groupId>
			<artifactId>jboss-marshalling</artifactId>
			<version>2.0.0.Beta2</version>
			<scope>runtime</scope>
		</dependency>
		<dependency>
			<groupId>org.jboss.weld.se</groupId>
			<artifactId>weld-se</artifactId>
			<version>2.2.15.Final</version>
			<scope>runtime</scope>
		</dependency>
		<dependency>
			<groupId>org.wildfly.security</groupId>
			<artifactId>wildfly-security-manager</artifactId>
			<version>1.1.2.Final</version>
			<scope>runtime</scope>
		</dependency>
	</dependencies>

[jamezp]

I don't see anything obviously wrong here. I'm working on a reproducer so hopefully soonish I'll be able to have a look.

It looks like maybe you're running this on zO/S. Do you see the same issue on other OS's too?

[jamezp]

Sorry for the delay. I finally was able to get a working sample together that shows logging does seem to be working for me, https://github.com/jamezp/issue-reproducer/tree/jberet-test. If you just build the issue-reproducer/generic and run mvn clean package && java -jar target//generic-issue-reproducer.jar it should show the logging and some System.out messages too.

[jamezp]

Just as a follow up I did test this with a J9 JVM and it seemed to work for me. Below is the output.

java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 8.0.5.0 - pxa6480sr5-20170905_01(SR5))
IBM J9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20170901_363591 (JIT enabled, AOT enabled)
J9VM - d56eb84
JIT  - tr.open_20170901_140853_d56eb84
OMR  - b033a01)
JCL - 20170823_01 based on Oracle jdk8u144-b01
jperkins@localhost ~/projects/jboss/issue-reproducer/generic (jberet-test) $ java -jar ./target/generic-issue-reproducer.jar 
INFO: org.jboss.weld.Version WELD-000900: 2.4.1 (Final)
INFO: org.jboss.weld.Bootstrap WELD-000101: Transactional services not available. Injection of @Inject UserTransaction not available. Transactional observers will be invoked synchronously.
INFO: org.jboss.weld.Bootstrap WELD-ENV-002003: Weld SE container STATIC_INSTANCE initialized
INFO: org.wildfly.reproducer.CountingItemReader Opened item reader
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 0
Logged from org.wildfly.reproducer.LoggingItemWriter with item 0
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 1
Logged from org.wildfly.reproducer.LoggingItemWriter with item 1
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 2
Logged from org.wildfly.reproducer.LoggingItemWriter with item 2
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 3
Logged from org.wildfly.reproducer.LoggingItemWriter with item 3
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 4
Logged from org.wildfly.reproducer.LoggingItemWriter with item 4
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 5
Logged from org.wildfly.reproducer.LoggingItemWriter with item 5
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 6
Logged from org.wildfly.reproducer.LoggingItemWriter with item 6
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 7
Logged from org.wildfly.reproducer.LoggingItemWriter with item 7
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 8
Logged from org.wildfly.reproducer.LoggingItemWriter with item 8
INFO: org.wildfly.reproducer.LoggingItemWriter Logged from org.wildfly.reproducer.LoggingItemWriter with item 9
Logged from org.wildfly.reproducer.LoggingItemWriter with item 9
INFO: org.wildfly.reproducer.CountingItemReader Closed item reader
Weld SE container STATIC_INSTANCE shut down by shutdown hook