Logger no VRaptor 3.5.3

Assuntos Gerais
#1

Olá pessoal,

Por algum motivo o Logger no projeto não está funcionando corretamente.
O Log do JBoss permanece inativo na console do Eclipse, somente se ocorrer alguma excessão o erro aparece na console, porém não exibe nenhum indicativo de que os métodos estão disponíveis para serem acessados na aplicação embora estejam sendo invocados.

O que eu quero dizer é que normalmente os métodos da Controller aparecem como disponíveis durante o start up do servidor de aplicação, o que não está ocorrendo.
Não sei se esse é um dos motivos para o Logger não estar funcionando ou está abafando a sua exibição na console, pois nem mesmo um print está sendo exibido na console.

Gostaria de informar que as configurações do JPA 2.0 estão funcionado perfeitamente, não está ocorrendo erros neste sentido, ou seja, a aplicação está conversando com o banco normalmente executando todas as operações do EntityManager.

Alguém poderia me ajudar a entender o comportamento?

Segue os arquivos de configuração do projeto.

Desde já agradeço a colaboração.

#2

log4j.xml

<?xml version="1.0" encoding="UTF-8" ?>
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

	<appender name="stdout" class=
	"org.apache.log4j.ConsoleAppender">
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern"
			value="%d{HH:mm:ss,SSS} %5p [%-20c{1}] %m%n"/>
		</layout>
	</appender>
	<category name="org.vraptor">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="br.com.caelum.vraptor">
		<priority value="DEBUG" />
		<appender-ref ref="stdout" />
	</category>
	<category name="com.thoughtworks">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="org.springframework">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="org.hibernate">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="com.mchange">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>

</log4j:configuration>
#3

log4j.properties

log4j.appender.stdout=org.apache.log4j.ConsoleAppender  
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout  
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss} %5p [%-20c{1}] %m%n  
  
log4j.rootLogger=warn, stdout  
  
log4j.logger.org.hibernate.SQL=DEBUG  # É equivalente ao hibernate.show_sql=true  
log4j.logger.org.hibernate.type=TRACE # Exibe os parâmetros JDBC

web.xml

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="http://java.sun.com/xml/ns/javaee" 
         xmlns:jsp="http://java.sun.com/xml/ns/javaee/jsp" 
         xmlns:web="http://java.sun.com/xml/ns/javaee" 
         xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd" 
         id="WebApp_ID" 
         version="2.5">
  <display-name>MajorJourneyEnterprise</display-name>
  <context-param>
    <param-name>javax.servlet.jsp.jstl.fmt.localizationContext</param-name>
    <param-value>messages</param-value>
  </context-param>
  <context-param>
    <param-name>br.com.caelum.vraptor.encoding</param-name>
    <param-value>UTF-8</param-value>
  </context-param>
  <context-param>
    <param-name>br.com.caelum.vraptor.packages</param-name>
    <param-value>br.com.caelum.vraptor.util.jpa</param-value>
  </context-param>  
  <filter>
    <filter-name>vraptor</filter-name>
    <filter-class>br.com.caelum.vraptor.VRaptor</filter-class>
  </filter>
  <filter>
    <filter-name>sitemesh</filter-name>
    <filter-class>com.opensymphony.sitemesh.webapp.SiteMeshFilter</filter-class>
  </filter>
  <filter-mapping>
    <filter-name>sitemesh</filter-name>
    <url-pattern>/*</url-pattern>
  </filter-mapping>
  <error-page>
    <error-code>404</error-code>
    <location>/404.html</location>
  </error-page>
  <filter-mapping>
    <filter-name>vraptor</filter-name>
    <url-pattern>/*</url-pattern>
    <dispatcher>FORWARD</dispatcher>
    <dispatcher>REQUEST</dispatcher>
  </filter-mapping>
  <jsp-config>
    <jsp-property-group>
      <url-pattern>*.jsp</url-pattern>
      <page-encoding>UTF-8</page-encoding>
      <include-prelude>/WEB-INF/jsp/prelude.jspf</include-prelude>
    </jsp-property-group>
  </jsp-config>
</web-app>
#4

Controller

package br.com.majorEnterpriseJourney.controller;

import java.math.BigDecimal;
import java.text.MessageFormat;
import java.util.ArrayList;
import java.util.Date;
import java.util.List;

import org.apache.log4j.Logger;

import br.com.caelum.vraptor.Get;
import br.com.caelum.vraptor.Post;
import br.com.caelum.vraptor.Resource;
import br.com.caelum.vraptor.Result;
import br.com.caelum.vraptor.Validator;
import br.com.majorEnterpriseJourney.interceptors.Publico;
import br.com.majorEnterpriseJourney.interceptors.UsuarioLogado;

import br.com.majorEnterpriseJourney.model.Usuario;
import br.com.majorEnterpriseJourney.service.UsuarioService;

@Resource
public class TesteController {

	private static final Logger LOG = Logger.getLogger(TesteController.class);
	
	private final Result result;
	private final Validator validator;
	private final UsuarioLogado usuarioLogado;
	private final UsuarioService usuarioService;
	
	public TesteController(Result result, Validator validator, UsuarioLogado usuarioLogado, UsuarioService usuarioService) {		
		this.result = result;
		this.validator = validator;
		this.usuarioLogado = usuarioLogado;
		this.usuarioService = usuarioService;
	}

	@Get
	@Publico	
	public void acessarDados() {
		listarUsuarios();	
	}
		
	public List<Usuario> listarUsuarios(){
	    LOG.debug("Testando o comportamento do LOG.");
		
		List<Usuario> lista = usuarioService.findAll();
		for (Usuario usuario : lista) {
			System.out.println(usuario.getId());	
			System.out.println(usuario.getSenha());
			System.out.println(usuario.getUsername());
			System.out.println(usuario.getDataCadastro());
			System.out.println(usuario.getIdUsuario());
			System.out.println(usuario.getFuncionario().getNome());			
		}
		return lista;
	}
	
	public static Logger getLog() {
		return LOG;
	}

	public Result getResult() {
		return result;
	}

	public Validator getValidator() {
		return validator;
	}
}
#5

Log do JBoss EAP 6.1.0.Alpha1

21:34:20,086 INFO  [org.jboss.modules] (main) JBoss Modules version 1.2.0.CR1
21:34:20,479 INFO  [org.jboss.msc] (main) JBoss MSC version 1.0.4.GA
21:34:20,574 INFO  [org.jboss.as] (MSC service thread 1-7) JBAS015899: JBoss EAP 6.1.0.Alpha1 (AS 7.2.0.Alpha1-redhat-4) starting
21:34:21,852 INFO  [org.jboss.as.server.deployment.scanner] (DeploymentScanner-threads - 1) JBAS015003: Found MajorEnterpriseJourney.war in deployment directory. To trigger deployment create a file called MajorEnterpriseJourney.war.dodeploy
21:34:21,871 INFO  [org.xnio] (MSC service thread 1-5) XNIO Version 3.0.7.GA
21:34:21,873 INFO  [org.jboss.as.server] (Controller Boot Thread) JBAS015888: Creating http management service using socket-binding (management-http)
21:34:21,894 INFO  [org.xnio.nio] (MSC service thread 1-5) XNIO NIO Implementation Version 3.0.7.GA
21:34:21,933 INFO  [org.jboss.remoting] (MSC service thread 1-5) JBoss Remoting version 3.2.14.GA
21:34:21,953 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 29) JBAS010280: Activating Infinispan subsystem.
21:34:21,974 INFO  [org.jboss.as.naming] (ServerService Thread Pool -- 37) JBAS011800: Activating Naming Subsystem
21:34:21,976 INFO  [org.jboss.as.security] (ServerService Thread Pool -- 42) JBAS013171: Activating Security Subsystem
21:34:21,989 INFO  [org.jboss.as.security] (MSC service thread 1-2) JBAS013170: Current PicketBox version=4.0.15.Final
21:34:21,998 INFO  [org.jboss.as.connector.logging] (MSC service thread 1-8) JBAS010408: Starting JCA Subsystem (JBoss IronJacamar 1.0.15.Final)
21:34:22,000 INFO  [org.jboss.as.jsf] (ServerService Thread Pool -- 35) JBAS012605: Activated the following JSF Implementations: [main, 1.2]
21:34:22,010 INFO  [org.jboss.as.webservices] (ServerService Thread Pool -- 46) JBAS015537: Activating WebServices Extension
21:34:22,159 INFO  [org.jboss.ws.common.management] (MSC service thread 1-16) JBWS022052: Starting JBoss Web Services - Stack CXF Server 4.1.3.Final
21:34:22,166 INFO  [org.jboss.as.naming] (MSC service thread 1-13) JBAS011802: Starting Naming Service
21:34:22,168 INFO  [org.jboss.as.mail.extension] (MSC service thread 1-11) JBAS015400: Bound mail session [java:jboss/mail/Default]
21:34:22,309 INFO  [org.apache.coyote.http11] (MSC service thread 1-8) JBWEB003001: Coyote HTTP/1.1 initializing on : http-localhost/127.0.0.1:8080
21:34:22,314 INFO  [org.apache.coyote.http11] (MSC service thread 1-8) JBWEB003000: Coyote HTTP/1.1 starting on: http-localhost/127.0.0.1:8080
21:34:22,512 INFO  [org.jboss.as.connector.subsystems.datasources] (ServerService Thread Pool -- 25) JBAS010403: Deploying JDBC-compliant driver class com.microsoft.sqlserver.jdbc.SQLServerDriver (version 4.0)
21:34:22,547 INFO  [org.jboss.as.server.deployment.scanner] (MSC service thread 1-16) JBAS015012: Started FileSystemDeploymentService for directory C:\Gustavo\Java\Workspaces\WkspaceUtils\jboss-eap-6.1\standalone\deployments
21:34:22,547 INFO  [org.jboss.as.remoting] (MSC service thread 1-12) JBAS017100: Listening on 127.0.0.1:9999
21:34:22,547 INFO  [org.jboss.as.remoting] (MSC service thread 1-14) JBAS017100: Listening on 127.0.0.1:4447
21:34:22,550 INFO  [org.jboss.as.server.deployment] (MSC service thread 1-4) JBAS015876: Starting deployment of "MajorEnterpriseJourney.war" (runtime-name: "MajorEnterpriseJourney.war")
21:34:22,753 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-9) JBAS010400: Bound data source [java:jboss/MajorEnterpriseJourneyDS]
21:34:28,020 WARN  [org.jboss.as.server.deployment] (MSC service thread 1-2) JBAS015893: Encountered invalid class name 'org.xmlpull.mxp1.MXParser,org.xmlpull.mxp1_serializer.MXSerializer' for service type 'org.xmlpull.v1.XmlPullParserFactory'
21:34:28,060 INFO  [org.jboss.as.jpa] (MSC service thread 1-2) JBAS011401: Read persistence.xml for default
21:34:28,775 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-8) JBAS010403: Deploying JDBC-compliant driver class org.hsqldb.jdbc.JDBCDriver (version 2.2)
21:34:28,779 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-8) JBAS010404: Deploying non-JDBC-compliant driver class com.mysql.jdbc.Driver (version 5.1)
21:34:28,780 WARN  [org.jboss.weld.deployer] (MSC service thread 1-8) JBAS016012: Deployment deployment "MajorEnterpriseJourney.war" contains CDI annotations but beans.xml was not found.
21:34:28,813 INFO  [org.jboss.as.jpa] (ServerService Thread Pool -- 48) JBAS011402: Starting Persistence Unit Service 'MajorEnterpriseJourney.war#default'
21:34:29,095 INFO  [org.hibernate.annotations.common.Version] (ServerService Thread Pool -- 48) HCANN000001: Hibernate Commons Annotations {4.0.1.Final}
21:34:29,099 INFO  [org.hibernate.Version] (ServerService Thread Pool -- 48) HHH000412: Hibernate Core {4.2.0.CR1}
21:34:29,101 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 48) HHH000206: hibernate.properties not found
21:34:29,102 INFO  [org.hibernate.cfg.Environment] (ServerService Thread Pool -- 48) HHH000021: Bytecode provider name : javassist
21:34:29,139 INFO  [org.hibernate.ejb.Ejb3Configuration] (ServerService Thread Pool -- 48) HHH000204: Processing PersistenceUnitInfo [
	name: default
	...]
21:34:29,775 INFO  [org.hibernate.service.jdbc.connections.internal.ConnectionProviderInitiator] (ServerService Thread Pool -- 48) HHH000130: Instantiating explicit connection provider: org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider
21:34:31,075 INFO  [org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 48) HHH000400: Using dialect: org.hibernate.dialect.SQLServerDialect
21:34:31,128 INFO  [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (ServerService Thread Pool -- 48) HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory
21:34:31,140 INFO  [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (ServerService Thread Pool -- 48) HHH000397: Using ASTQueryTranslatorFactory
21:34:31,312 INFO  [org.hibernate.validator.internal.util.Version] (ServerService Thread Pool -- 48) HV000001: Hibernate Validator 4.3.1.Final
21:34:32,314 WARN  [org.hibernate.internal.SessionFactoryImpl] (ServerService Thread Pool -- 48) HHH000008: JTASessionContext being used with JDBCTransactionFactory; auto-flush will not operate correctly with getCurrentSession()
21:34:32,711 INFO  [org.jboss.web] (ServerService Thread Pool -- 56) JBAS018210: Register web context: /MajorEnterpriseJourney
21:34:34,498 INFO  [org.hibernate.dialect.Dialect] (ServerService Thread Pool -- 56) HHH000400: Using dialect: org.hibernate.dialect.SQLServerDialect
21:34:34,501 INFO  [org.hibernate.engine.transaction.internal.TransactionFactoryInitiator] (ServerService Thread Pool -- 56) HHH000268: Transaction strategy: org.hibernate.engine.transaction.internal.jdbc.JdbcTransactionFactory
21:34:34,501 INFO  [org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory] (ServerService Thread Pool -- 56) HHH000397: Using ASTQueryTranslatorFactory
21:34:34,973 INFO  [org.jboss.as.server] (ServerService Thread Pool -- 26) JBAS018559: Deployed "MajorEnterpriseJourney.war" (runtime-name : "MajorEnterpriseJourney.war")
21:34:35,272 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015961: Http management interface listening on http://127.0.0.1:9990/management
21:34:35,272 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015951: Admin console listening on http://127.0.0.1:9990
21:34:35,272 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.1.0.Alpha1 (AS 7.2.0.Alpha1-redhat-4) started in 15950ms - Started 337 of 394 services (56 services are passive or on-demand)

Os arquivos do log4j encontram-se neste caminho do projeto.

src/main/resources
	log4j.properties
	log4j.xml
#6

Vc tem que remover ou o log4j.properties ou o log4j.xml, os dois fazem a mesma coisa e uma config pode sobrescrever a outra.

2a coisa: vc precisa acertar os níveis dos logs.

vc fez um LOG.debug(…), mas o root logger (do properties) está como WARN. (ou seja, só loga mesmo o WARN e ERROR)

sugestão: remova o .properties e adicione isso ao .xml:

 <category name="br.com.pacote.da.sua.app">  
        <priority value="DEBUG" />  
        <appender-ref ref="stdout" />  
    </category>
#7

Lucas,

Removi o arquivo log4j.properties e alterei o log4j.xml para:

<?xml version="1.0" encoding="UTF-8" ?>
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

	<appender name="stdout" class=
	"org.apache.log4j.ConsoleAppender">
		<layout class="org.apache.log4j.PatternLayout">
			<param name="ConversionPattern"
			value="%d{HH:mm:ss,SSS} %5p [%-20c{1}] %m%n"/>
		</layout>
	</appender>
	<category name="org.vraptor">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="br.com.caelum.vraptor">
		<priority value="DEBUG" />
		<appender-ref ref="stdout" />
	</category>
	<category name="com.thoughtworks">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="org.springframework">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="org.hibernate">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	<category name="com.mchange">
		<priority value="INFO" />
		<appender-ref ref="stdout" />
	</category>
	
	<category name="br.com.majorEnterpriseJourney">    
		<priority value="DEBUG" />    
		<appender-ref ref="stdout" />    
	</category> 	

</log4j:configuration>

Não aconteceu nada de diferente, alguma outra idéia?

#8

os nomes de pacotes em java não deveriam ter letra maiúsculas, mas acho que não deveria ser esse o problema…

vc consegue fazer o deploy dessa aplicação em outro servidor, tipo um tomcat, e ver se aparecem os logs?

#9

Ok Lucas, vou simplificar os pacotes seguindo a sugestão.

Pretendo configurar o projeto no Tomcat também, como experiência, mas prefiro não descartar a possibilidade de usar EJB no projeto, neste caso o ideal seria manter o JBoss.
Alguma outra sugestão?

#10

a parte de colocar no Tomcat é só pra ver se o problema é no projeto ou no servidor.

#11

Lucas,

Pesquisei sobre o assunto e descobri que existe uma configuração no JBoss para ativar o logger para ser executado na aplicação, pois as configurações padrão do appserver sobrepõem o log4j e seus arquivos de serem executados no caso do JBoss.

A tag no arquivo standalone.xml ou domain.xml é a subsystem xmlns="urn:jboss:domain:logging

Acrescentei o logger category do VRaptor e o Logger começou a ser exibido na console conforme esperado.
Porém não está gravando as minhas ações quando determinado.

Testei dessas duas formas e não escreve no log.
LOG.info(“Testando o comportamento do LOG.”);
LOG.debug(“Testando o comportamento do LOG.”);

Olhei o arquivo gerado server.log e está exibindo exatamente o que está aparecendo na console.
System.out.println(“Qualquer coisa”); também não funciona.

Este é o subsystem configurado no momento no standalone.xml

		<subsystem xmlns="urn:jboss:domain:logging:1.0">
		   <console-handler name="CONSOLE" autoflush="true">
			   <level name="DEBUG"/>
			   <formatter>
				   <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
			   </formatter>
		   </console-handler>
		   <periodic-rotating-file-handler name="FILE" autoflush="true">
			   <formatter>
				   <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
			   </formatter>
			   <file relative-to="jboss.server.log.dir" path="server.log"/>
			   <suffix value=".yyyy-MM-dd"/>
		   </periodic-rotating-file-handler>
		   <logger category="com.arjuna">
			   <level name="WARN"/>
		   </logger>
		   <logger category="br.com.caelum.vraptor">
			   <level name="INFO"/>
		   </logger>
		   <root-logger>
			   <level name="DEBUG"/>
			   <handlers>
				   <handler name="CONSOLE"/>
				   <handler name="FILE"/>
			   </handlers>
		   </root-logger>
		</subsystem>
#12

Será que está faltando ativar alguma propriedade? Tem alguma idéia?

#13

Lucas,

Após enviar a última mensagem eu lembrei que ainda não tinha removido o arquivo log4j.xml do projeto, eu havia apenas removido o log4j.properties.
Assim que removi e refiz o startup do JBoss a aplicação começou a gravar o logger no server.log e exibir perfeitamente na console.

Valeu mesmo pela ajuda. Espero que outras pessoas possam se beneficiar pela experiência.
Grande abraço.

#14