< Sergii Kostenko's blog

Logging for JPA SQL queries with Wildfly

10 January 2020

Logging for real SQL queries is very important in case using any ORM solution, - as you never can be sure which and how many requests will send JPA provider to do find, merge, query or some other operation.

Wildfly uses Hibernate as JPA provider and provides few standard ways to enable SQL logging:

1. Add hibernate.show_sql property to your persistence.xml :

<properties>
    ...
    <property name="hibernate.show_sql" value="true" />
    ...
</properties>
INFO  [stdout] (default task-1) Hibernate: insert into blogentity (id, body, title) values (null, ?, ?)
INFO  [stdout] (default task-1) Hibernate: select blogentity0_.id as id1_0_, blogentity0_.body as body2_0_, blogentity0_.title as title3_0_ from blogentity blogentity0_ where blogentity0_.title=?

2. Enable ALL log level for org.hibernate category like:

/subsystem=logging/periodic-rotating-file-handler=sql_handler:add(level=ALL, file={"path"=>"sql.log"}, append=true, autoflush=true, suffix=.yyyy-MM-dd,formatter="%d{yyyy-MM-dd HH:mm:ss,SSS}")
/subsystem=logging/logger=org.hibernate.SQL:add(use-parent-handlers=false,handlers=["sql_handler"])
/subsystem=logging/logger=org.hibernate.type.descriptor.sql.BasicBinder:add(use-parent-handlers=false,handlers=["sql_handler"])
DEBUG [o.h.SQL] insert into blogentity (id, body, title) values (null, ?, ?)
TRACE [o.h.t.d.s.BasicBinder] binding parameter [1] as [VARCHAR] - [this is body]
TRACE [o.h.t.d.s.BasicBinder] binding parameter [2] as [VARCHAR] - [title]
DEBUG [o.h.SQL] select blogentity0_.id as id1_0_, blogentity0_.body as body2_0_, blogentity0_.title as title3_0_ from blogentity blogentity0_ where blogentity0_.title=?
TRACE [o.h.t.d.s.BasicBinder] binding parameter [1] as [VARCHAR] - [title]

3. Enable spying of SQL statements:

/subsystem=datasources/data-source=ExampleDS/:write-attribute(name=spy,value=true)
/subsystem=logging/logger=jboss.jdbc.spy/:add(level=DEBUG)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [DataSource] getConnection()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [Connection] prepareStatement(insert into blogentity (id, body, title) values (null, ?, ?), 1)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [PreparedStatement] setString(1, this is body)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [PreparedStatement] setString(2, title)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [PreparedStatement] executeUpdate()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [PreparedStatement] getGeneratedKeys()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] next()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] getMetaData()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] getLong(1)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] close()
...
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [DataSource] getConnection()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [Connection] prepareStatement(select blogentity0_.id as id1_0_, blogentity0_.body as body2_0_, blogentity0_.title as title3_0_ from blogentity blogentity0_ where blogentity0_.title=?)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [PreparedStatement] setString(1, title)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [PreparedStatement] executeQuery()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] next()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] getLong(id1_0_)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] wasNull()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] getString(body2_0_)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] wasNull()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] getString(title3_0_)
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] wasNull()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] next()
DEBUG [j.j.spy] java:jboss/datasources/ExampleDS [ResultSet] close()

So, from above we can see that variants 2 and 3 is most useful as allows to log queries with parameters. From other point of view - SQL logging can generate lot of unneeded debug information on production. To avoid garbage data in your log files, feel free to use Filter Expressions for Logging

Comments


Why Jakarta EE beats other java solutions from security point of view

27 December 2019

No one care about security until security incident. In case enterprise development last one can costs too much, so any preventive steps can help. Significant part part of the OWASP Application Security Verification Standard (ASVS) reads:

10.2.1 Verify that the application source code and third party libraries do not contain unauthorized phone home or data collection capabilities. Where such functionality exists, obtain the user's permission for it to operate before collecting any data.
10.2.3 Verify that the application source code and third party libraries do not contain back doors, such as hard-coded or additional undocumented accounts or keys, code obfuscation, undocumented binary blobs, rootkits, or anti-debugging, insecure debugging features, or otherwise out of date, insecure, or hidden functionality that could be used maliciously if discovered.
10.2.4 Verify that the application source code and third party libraries does not contain time bombs by searching for date and time related functions.
10.2.5 Verify that the application source code and third party libraries does not contain malicious code, such as salami attacks, logic bypasses, or logic bombs.
10.2.6 Verify that the application source code and third party libraries do not contain Easter eggs or any other potentially unwanted functionality.
10.3.2 Verify that the application employs integrity protections, such as code signing or sub-resource integrity. The application must not load or execute code from untrusted sources, such as loading includes, modules, plugins, code, or libraries from untrusted sources or the Internet.
14.2.4 Verify that third party components come from pre-defined, trusted and continually maintained repositories.

In other words that meaning you should: "Verify all code including third-party binaries, libraries, frameworks are reviewed for hardcoded credentials (backdoors)."

In case development according to Jakarta EE specification you shouldn't be able to use poor controlled third party libraries, as all you need already came with Application Server. In turn, last one is responsible for in time security updates, ussage of verified libraries and many more...

Comments


How to setup Darcula LAF on Netbeans 11

26 December 2019

It is pity, but Apache Netbeans IDE still comes without support default dark mode. Enabling Netbeans 8.2 Plugin portal does not have any effect, so to use plugins from previous versions we need to add New Provider (Tools->Plugins) with next URL:

http://plugins.netbeans.org/nbpluginportal/updates/8.2/catalog.xml.gz

add provider

After that you should be able setup Darcula LAF in standard way

add provider

Comments


Understanding JMS(MDB) transaction scopes in JakartaEE application

14 November 2019

Most useful way to deal with JMS in JakartaEE application is MDB(Message Driven Beans). This type of bean acts as a JMS message listener to which messages can be delivered from either a queue or a topic.

Message Driven Bean supports only Required and NotSupported scopes as there is no incoming transaction context.

In both cases above, when message was returned to the destination, container will do redelivery according to application server configuration. For example on Wildfly it is: max-delivery-attempts and redelivery-delay.

/subsystem=messaging-activemq/server=default/address-setting=#:read-attribute(name=max-delivery-attempts)

Be careful with redelivery configuration as in case "poisen message" it can negative affect performance of your application or even server.

When you use container-managed transactions, you can invoke next MessageDrivenContext methods:

In case bean-managed transactions you need to manually control transaction by UserTransaction methods and you also can set the activation configuration property acknowledgeMode to Auto-acknowledge or Dups-ok-acknowledge to specify how the message received by the message-driven bean to be acknowledged.

Ok. Let's pay attention on typical use cases and potentially issues with default configurations. Often enough developers use MDB to do relatively long tasks that should be executed asynchronously. So typical message bean in this case will looks like:

@JMSDestinationDefinition(
        name = TxRequiredMessagerDrivenBean.TX_REQUIRED_QUEUE,
        interfaceName = "javax.jms.Queue"
)
@MessageDriven(activationConfig = {
    @ActivationConfigProperty(propertyName = "destinationLookup", propertyValue = TxRequiredMessagerDrivenBean.TX_REQUIRED_QUEUE),
    @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue")
})
//@TransactionAttribute(TransactionAttributeType.REQUIRED)
public class TxRequiredMessagerDrivenBean implements MessageListener {

    public final static String TX_REQUIRED_QUEUE = "java:global/jms/txRequiredQueue";

    @Resource
    MessageDrivenContext messageDrivenContext;

    @Override
    public void onMessage(Message msg) {
        System.out.println("Got new message.");
        try {
            System.out.println("Hello TxRequiredMessagerDrivenBean!");
            for (int x = 1; x < 40; x++) {
                Thread.sleep(10_000l);
                System.out.println("Long transaction: " + (10 * x) + " sec.");
            }
        } catch (Exception ex) {
            System.err.println(ex);
            messageDrivenContext.setRollbackOnly();
        }
        System.out.println("Message  successfully processed");
    }
}

Now take a look to result of our bean invocation:

INFO  (Thread-1 (ActiveMQ-client-global-threads)) Got new message.
INFO  (Thread-1 (ActiveMQ-client-global-threads)) Hello TxRequiredMessagerDrivenBean!
INFO  (Thread-1 (ActiveMQ-client-global-threads)) Long transaction: 10 sec.
...
INFO  (Thread-1 (ActiveMQ-client-global-threads)) Long transaction: 290 sec.
...
WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:3b3ecbca:5dcc2894:13 in state  RUN
WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:3b3ecbca:5dcc2894:13 invoked while multiple threads active within it.
WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff7f000101:3b3ecbca:5dcc2894:13 completed with multiple threads - thread Thread-1 (ActiveMQ-client-global-threads) was in progress with java.lang.Thread.sleep(Native Method) org.kostenko.example.jms.transaction.TxRequiredMessagerDrivenBean.onMessage(TxRequiredMessagerDrivenBean.java:40)
...
WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:3b3ecbca:5dcc2894:13 aborting with 1 threads active!
...
WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:3b3ecbca:5dcc2894:13
...
INFO  (Thread-3 (ActiveMQ-client-global-threads)) Got new message.
INFO  (Thread-3 (ActiveMQ-client-global-threads)) Hello TxRequiredMessagerDrivenBean!
INFO  (Thread-1 (ActiveMQ-client-global-threads)) Long transaction: 300 sec.
INFO  (Thread-3 (ActiveMQ-client-global-threads)) Long transaction: 10 sec.
INFO  (Thread-1 (ActiveMQ-client-global-threads)) Long transaction: 310 sec.
INFO  (Thread-3 (ActiveMQ-client-global-threads)) Long transaction: 20 sec.
INFO  (Thread-1 (ActiveMQ-client-global-threads)) Long transaction: 320 sec.
...
INFO  (Thread-3 (ActiveMQ-client-global-threads)) [] Long transaction: 90 sec.
INFO  (Thread-1 (ActiveMQ-client-global-threads)) [] Long transaction: 390 sec.
INFO  (Thread-1 (ActiveMQ-client-global-threads)) [] Message  successfully processed
WARN  [com.arjuna.ats.arjuna] (Thread-1 (ActiveMQ-client-global-threads)) [] ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:3b3ecbca:5dcc2894:13
WARN  [org.apache.activemq.artemis.ra] (Thread-1 (ActiveMQ-client-global-threads)) [] AMQ152006: Unable to call after delivery: javax.resource.spi.LocalTransactionException: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:3b3ecbca:5dcc2894:13
  Caused by: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:3b3ecbca:5dcc2894:13
...
WARN  [org.apache.activemq.artemis.core.client] (Thread-1 (ActiveMQ-client-global-threads)) [] AMQ212009: resetting session after failure

From log above we can see that:

So, keep this behavior in mind if you planning to play with long tasks and Message Driven Beans then depends on requirements few solutions is possible here:

@MessageDriven(activationConfig = {
    @ActivationConfigProperty(propertyName = "destinationLookup", propertyValue = TxRequiredMessagerDrivenBean.TX_REQUIRED_QUEUE),
    @ActivationConfigProperty(propertyName = "destinationType", propertyValue = "javax.jms.Queue")
    @ActivationConfigProperty(propertyName = "transactionTimeout", propertyValue="500")
})

Source code of test application available on GitHub

Comments


Never use Java primitives for math calculation

08 November 2019

This is well known stuff about representation of Floating point types in java, but time from time each developer can forget about

@Test
public void primitiveTest() {

    // right way:
    BigDecimal bgDcml = BigDecimal.valueOf(100000f).multiply(BigDecimal.valueOf(750f)).multiply(BigDecimal.valueOf(15f)).setScale(0);
    BigDecimal bgDcml2 = BigDecimal.valueOf(0.04d).multiply(BigDecimal.valueOf(15.0d));

    // wrong way:
    float flt = 100000f * 750f * 15f;
    float flt2 = 0.04f * 15.0f;

    System.out.println("BigDecimal (correct): " + bgDcml);
    System.out.println(String.format("Float (incorrect): %s (%s)", flt, new BigDecimal(flt)));
    System.out.println("BigDecimal (correct): " + bgDcml2);
    System.out.println(String.format("Float (incorrect): %s", flt2));
}
-------------------------------------------------------
 T E S T S
-------------------------------------------------------
BigDecimal (correct): 1125000000
Float (incorrect): 1.12499994E9 (1124999936)
BigDecimal (correct): 0.600
Float (incorrect): 0.59999996

Comments