QBeans have a very simple lifecycle:

• init
• start
• stop
• destroy

When Q2 starts, it reads all the QBeans available in the deploy directory and calls init on all of them, then start, using alphabetical order. That's the reason we have an order convention: 00* for the loggers, 10* for the channels, 20* for the MUXes, 30* for the TransactionManagers, etc.

This startup lifecycle has served us well for a very long time, but when we start getting creative with the Environment and the Environment Providers, things start to get awkward.

With the environment providers, we can dereference configuration properties from YAML files, Java properties, or operating system variables. These variables can have a prefix that indicates we need to call a provider loaded via a ServiceLoader. For example, an HSM environment provider allows you to use properties like this: hsm::xxxxxx, where xxxxxx is a cryptogram encrypted under the HSM's LMKs.

To decrypt xxxxxx, we need to call the HSM driver, typically configured using a QBean.

Imagine this deploy directory:

20_hsm_driver.xml
25_cryptoservice.xml

The cryptoservice wants to pick some configuration properties (such as its PGP private key passphrase) using the HSM, but it needs the HSM driver to be already started.

Up until now, Q2 would have called:

• hsm_driver: init method
• cryptoservice: init method

But the cryptoservice, at init time, needs to block until the hsm_driver is fully operational, which requires its start callback to be called.

The solution is simple: we now have an eager-start attribute:

<qbean name="xxx" class="org.jpos.xxx.QBeanXXX" eager-start="true">
  ...
  ...
</qbean>

When Q2 sees a QBean with the eager-start attribute set to true, it starts it right away.

In jPTS’ user interface, we need a way to click on a given card and show all transactions for that card over a specified period of time. Because all sensitive data is stored using AES-256 in the secureData column of the tl_capture table using the CryptoService—a column that can be further encrypted at the database level—we need a lightweight, database index-friendly, one-way consistent hash of the primary account number.

Because computing a hash these days is an extremely fast operation, knowing the last four digits of a 16-digit PAN and the hash is enough information to brute-force the full PAN in a matter of milliseconds. Therefore, jPTS uses a dynamic per-BIN secret that incorporates several layers of defense.

Here is a screenshot of the UI page that requires this feature. When you click on a specific card, the transactions for that card alone are displayed.

The 128-bit SHA-1 algorithm, the same as other hash algorithms can be brute forced to produce a collision under certain circumstances. With today’s CPUs, finding a collision would take approximately 2600 years, a time that can be reduced to about 100 years using a cluster of GPUs. In 2017, the first collision for SHA-1 ¹ was found. Further research has provided additional cryptanalysis strategies that could theoretically reduce this time to approximately 24 days. (See also ²³⁴⁵).

Understanding Collisions​

Imagine you have a PDF file that has the SHA-1 hash:

845cfdca0ba5951580f994250cfda4fee34a1b58

Using the techniques mentioned above, it is theoretically feasible to find another file different from the original one that has the same hash, though this requires significant computing effort. However, this scenario applies to large files, not to small 16 to 19 digit Primary Account Numbers (PANs).

When dealing with a limited number of digits, especially where the last digit must satisfy a modulus 10 condition (LUHN)⁶, finding a collision is not possible as there are no collissions. Studies have shown that the minimum size for a collision is approximately 422 bytes⁷. This refers to full 8-bit bytes, not just a restricted pattern within the ASCII range of 0x30 to 0x39 (representing digits 0 through 9).

Going to an extreme, imagine you have just one digit, from 0 to 9:

You can see there are no collisions. If we add two digits, there are no collisions either. With three digits, still none. Even with 16 digits, none. At 19 digits, none. And with 100 digits, still none. The shortest collision theoretically possible is around 422 bytes, but we're talking about full 8-bit bytes here, not just limited to the scope of 0x30 to 0x39 values, which also need to honor the LUHN algorithm.

SHA-1 in the wild​

Git, the most widely used source control system in the world, uses SHA-1. In 2017, Linus Torvalds commented on this:

I doubt the sky is falling for Git as a source control management tool.⁸

And indeed, the sky was not falling. Fast forward to 2024, and Git still uses SHA-1. While it makes sense for Git to consider moving to another algorithm because finding a collision is theoretically feasible (though quite more difficult than in a PDF due to Git internal indexing constraints), this is just not possible in the jPTS case where we deal with limited PAN numbers.

Understanding Hash Functions​

In Java applications, all objects have an internal hashCode that is used in collections, maps, sets, caches, and more. The hashCode is typically quite simple, often auto-generated by IDEs, and can result in many collisions. Collisions are not a problem if they are properly handled. Despite the potential for collisions, this simple hash is very useful for placing objects into different buckets for indexing purposes. The popular and reliable Amazon DynamoDB, for example, uses MD5 (a hashing algorithm more prone to collisions than SHA-1) to derive partition keys. This does not mean that Amazon DynamoDB is insecure.

SHA-1 is designed to be collision-resistant, meaning it should be computationally infeasible to find two different inputs that produce the same hash output. Although SHA-1 has been shown to have vulnerabilities, leading to the discovery of practical collision attacks, these attacks require a large amount of computational power and typically involve much larger and more complex inputs than a simple 16-19 digit number.

The space of possible PANs, even considering 16-19 digits and a final LUHN check digit, is relatively small compared to the space of possible SHA-1 hash outputs (2^160 possible outputs). This means that the likelihood of any two distinct PANs producing the same SHA-1, as mentioned above, is just not possible.

Worst Case Scenario​

Imagine that all of this is wrong and SHA-1 is totally broken, allowing a malicious user to easily find a PAN collision. In such a scenario, an operator might see a screen of transactions with more than one card. While this situation is highly improbable, as described above, if all our theories were wrong, this would be the outcome. It would not be a major issue or a security problem. If such a situation were to occur, implementing compensating controls to detect duplicates would be quite straightforward, and the case could be presented at security conferences.

HMAC SHA-256​

For the reasons explained above, we believe SHA-1 is a good trade-off between security, performance, and database/storage use. That said, there are situations where and audit can go South due to a cognitive mismatch with the QSA/CISO. In those cases, using HMAC SHA-256 can be a solution.

SHA-3 (FIPS 202)​

We could use SHA-3 for this use case and avoid the need for this explanation, but the problem is that SHA-3 is overkill for such a simple use case. The previous sample hash would be quite longer:

5b6791cfd813470437bbea989ecfbd006571d89eeebe809fdb8e742b67e62a6e1a256eb57df90353065aa31e999724e0

and would put unnecessary pressure on the database and the indexes would be larger without any real benefit. Some QSAs have suggested using a truncated version of SHA-3 to meet the requirement of using SHA-3 while still maintaining a lightweight index.

However, we reject this approach because it would involve inventing our own cryptographic method. We do not have sufficient expertise in cryptography and mathematics (and obviously neither does the QSA) to determine whether a truncated SHA-3 would be less prone to collisions than SHA-1. What we do know is that creating cryptographic algorithms without a deep understanding is a recipe for problems.

Prove me wrong—how hard could it be?​

Show me two PANs with the same BIN (since we seed by BIN), a proper LUHN and the same SHA-1 hash and I'll hire you for our next audit.

Update​

I had a great conversation with my friend and QSA @dbergert about this post and he provided excellent pointers to the latest requirements as well as his expert opinion on this issue.

NIST will retire SHA-1 by 2030⁹ and since 2017 it is not permitted for authentication, which is not the case.

He agrees that collisions are not a concern here. However, the valid issue he raises is that simply hashing the PAN makes it vulnerable to brute force attacks. This is not the case here, and in fact, the same concern applies to SHA-3. Due to hardware acceleration, SHA-3 can be even faster than SHA-1.

Therefore, requesting a switch from SHA-1 to SHA-3 is somewhat naïve, as this is not what the PCI standard requires. He pointed me to this PCI FAQ: What is the Council's guidance on the use of SHA-1?. Here are some highlights:

The continued use of SHA-1 is permitted in only in the following scenarios:

1. Within top-level certificates (the Root Certificate Authority), which is the trust anchor for the hierarchy of certificates used. [✓] not the case.
2. Authentication of initial code on ROM that initiates upon device startup (note: all subsequent code must be authenticated using SHA-2). [✓] certainly not the case.
3. In conjunction with the generation of HMAC values and surrogate PANs (with salt), for deriving keys using key derivation functions (i.e., KDFs) and random number generation.

We "almost" land in case number 3 as the secure seed is equivalent to HMAC in this case, BUT, Dave has a very valid point:

I'm guessing that the PCI council is movig to HMAC's because those are well defined vs the myriad of ways a salted hash could be done, and security around the "salt".

That's a very reasonable concern, and I understand it. Our approach is just one of the many ways this can be implemented. Migrating to HMAC instead makes complete sense, regardless of the use of SHA-1 or SHA-3.

/by Barzilai Spinak a.k.a. @barspi a.k.a. The Facilitator/

Many jPOS users are familiar with the MUXPool class. In short, it's a MUX that sits in front of multiple muxes (usually QMUX) and will choose among them using some configured strategy. The client code, such as a SelectDestination participant in the transaction manager, will just talk to the MUXPool (i.e., call the request() method), without worrying about the underlying muxes, how many there are, whether they are available, etc.

Imagine you need to send messages to some issuer Bank ABC, and they have given you three connection endpoints (IPs and ports) for load balance or redundancy. In a typical configuration you would have three ChannelAdaptors and three matching muxes: let's call them abc1, abc2, and abc2. Your business logic will decide that "this transaction should go to Bank ABC", choosing a mux called BankABC.

So, you could configure a MUXPool with a nice symbolic name such as BankABC like this:

<mux class="org.jpos.q2.iso.MUXPool" logger="Q2" name="BankABC">
  <muxes>abc1 abc2 abc3</muxes>
  <strategy>round-robin</strategy>
</mux>

In this example, it would choose among the three muxes using a round robin strategy, among the "usable" muxes. So, if abc2 is not usable at the moment, then the choice would happen between abc1 and abc3 (the concept of "usable" applies mostly to implementations that honor the isConnected() method, such as QMUX, but this is another topic for another time).

New tricks for an old dog​

The built-in strategies for MUXPool, which we won't discuss here, are:

• round-robin
• round-robin-with-override
• split-by-divisor
• and the default, internally called PRIMARY_SECONDARY, which basically goes through the list in order until it finds the first usable mux.

Those strategies have existed for ages (git is telling me "9 years ago" for the latest addition of some of them). But for some time now, since around april 2023, there's a new trick: The inner interface MUXPool.StrategyHandler.

This is what it looks like, right from the jPOS source code:

public interface StrategyHandler {
    /** If this method returns null, the {@link MUXPool} will fall back to the configured built-in
     *  strategy.
     *
     * @param pool the {@link MUXPool} using this strategy handler
     * @param m the {@link ISOMsg} that we wish to send
     * @param maxWait deadline in milliseconds (epoch value as given by {@code System.currentTimeMillis()})
     * @return an appropriate {@link MUX} for this strategy, or {@code null} if none is found
     */
    MUX getMUX(MUXPool pool, ISOMsg m, long maxWait);
}

If the Javadoc is not clear enough, an instance of StrategyHandler will be called by the MUXPool, passing a reference to itself (pool), the ISOMsg we intend to send, and a timeout for the response.

This is how you could configure your MUXPool with a StrategyHandler:

<mux class="org.jpos.q2.iso.MUXPool" logger="Q2" name="BankABC">
  <muxes>abc1 abc2 abc3</muxes>

  <!-- The default, fall-back strategy -->
  <strategy>round-robin</strategy>

  <strategy-handler class="xxx.yyy.MyPoolStrategy">
    <!-- some config properties here -->
  </ strategy-handler>
</mux>

So, you implement the MyPoolStrategy, and your getMUX() method can choose among the available muxes using some other strategy. It's convenient to invoke the String[] getMuxNames() method of the given pool, and then you could use the NameRegistrar to get a reference to the muxes. You then could, for example, query some metrics from the underlying muxes (such as the ones provided by QMUX) to make your decision of the best mux to use.

If your _ StrategyHandler_ can't decide, then you just return null and the configured <strategy> will be used as a fall-back.

Some ideas for strategies include:

• Use the getRxPending() method of QMUX to get an estimate of which mux is more loaded, or slower to respond.
• Use the getIdleTimeInMillis() of QMUX to find a mux that hasn't been used recently.
• Take a look at the MTI of the ISOMsg to send reversals to a different destination from authorizations.
• A weighted round-robin, perhaps using some custom property of your muxes (such as subclass of QMUX), or configuring the weights in the strategy handler itself (hint: they can be Configurable so they can have their own configuration properties in the XML)

There may be alternate ways to implement similar behavior using other jPOS components, but the MUXPool.StrategyHandler may be a nice trick to keep in mind, and make some logic simpler.

Your imagination is the limit!

In 2007, a long time ago, when hardware was not as fast as it is today, we introduced CONTINUATIONS that had the ability to PAUSE (or park) a given transaction while waiting for a response from a remote server. Think of it as some kind of reactive programming.

If you have, say, a 4 CPU machine and need to process one thousand simultaneous transactions, without continuations you would need to set your TransactionManager sessions to a disproportionately large number (such as 1000), which has no relation to your hardware, making the entire system slower due to the context switch overhead.

With continuations, a small number of sessions (e.g., twice the number of CPUs you have) can handle a large number of transactions, because those waiting for a response are offloaded from the transaction manager until the response arrives.

The typical candidate for continuations is the QueryHost participant, which is implemented like this:

  mux.request(m, t, this, ctx);
  return PREPARED | READONLY | PAUSE | NO_JOIN;

The PAUSE modifier tells the TM to park that particular transaction until the context is resumed as part of its Pausable interface implementation. For the record, Pausable looks like this:

public interface Pausable {
    void setPausedTransaction(PausedTransaction p);
    ...
    ...
    void resume();
}

and the standard TransactionManager’s Context (org.jpos.transaction.Context) implements it.

When we call the asynchronous mux.request implementation and pass it an ISOResponseListener (QueryHost implements ISOResponseListener) and the current Context as a handback object, the transaction gets resumed and queued back with high priority when a response is received or the MUX times out, allowing it to be picked up by the next available session in the TransactionManager.

Futures were not popular in those days. Otherwise, the void request(ISOMsg m, long timeout, ISOResponseListener r, Object handBack) signature of the MUX’s asynchronous call would have probably been implemented using them.

QueryHost, which uses QMUX, as well as many other participants such as HttpQuery in jPOS-EE, use this facility to handle a large number of simultaneous transactions without requiring a large number of sessions—which would require a platform thread—in their transaction manager and are guaranteed to resume the context so that the transaction can continue its route within the TransactionManager.

This delicate mechanism works very well at production sites processing billions of transactions. However, we can’t guarantee that user-implemented participants can reliably time out, always, sooner or later, to complete the transaction and avoid a memory leak.

And here comes the reason for this post: In situations where participants may pause a transaction and not resume it after a timeout, we have a pause-timeout optional property that you can configure in the TransactionManager, e.g.:

xml

<property name="pause-timeout" value="300000" />

This is a safety net for those situations. If for some reason your participant doesn’t resume, the TransactionManager will auto-resume it for you after a reasonable amount of time to prevent a memory leak. Contexts are lightweight and consume little memory, so those leaks manifest themselves after several days or even weeks depending on your system load, making 5 minutes a reasonable default.

But the pause-timeout feature comes at a price. For every Context that we pause, a TimerTask is created to cancel the transaction. TimerTasks, popular 20 years ago, are quite brittle as they rely on a single platform thread calling every TimerTask Runnable WITHOUT CATCHING unchecked exceptions, which can cause the entire Timer facility to fail and create significant problems for other components such as the TSpace’s garbage collector.

Takeaways​

• The pause-timeout feature can be used if you fear your pausable participants may not resume. It’s usually used for debugging purposes after you experience warnings related to high in-transit transactions. A high in-transit indicates that at least one transaction got stuck without ever finishing. You can see this in the log by noticing that the tail ID gets stuck and doesn’t move up.

• If you decide to use a pause-timeout, remember that this is a safety net that should never be necessary. Setting a short timeout conflicting with the timeout you use at QueryHost (e.g., 15 seconds, or 30 seconds) is not advisable because it increases the chances of a race condition between the normal resume caused by the QueryHost expiration and the resume caused by the TimerTask runnable trying to do the same. If you use a pause-timeout, make it a long one.

Final Comment​

All this goes away in jPOS 3. Continuations make no sense in jPOS 3’s TransactionManager because sessions are handled by virtual threads, making it entirely feasible to have a large number of sessions in the 100k range. All the delicate asynchronous programming we required almost 20 years ago is now magically handled by Project Loom’s virtual threads.

jPOS Structured Audit Log (SAL)​

The jPOS XML logs, written a quarter of a century ago, were intended to serve as an audit trail capable of being reprocessed later in the event of a major system failure. Over the years, they proved to be very useful, saving the day during migrations, testing, and even production issues.

Originally, these logs were structured audit logs, similar to what we aim to achieve now. However, as the system grew, the highly flexible Loggeable interface was sometimes improperly implemented, occasionally resulting in invalid XML. While still reasonably intelligible to the human eye, this made it difficult to parse the XML content automatically. Moreover, PCI requirements have become stricter over the years (there was no PCI 25 years ago, it was the Wild West), and data that might be needed to reprocess a transaction is now entirely masked.

The term log, much like byte, is widely overused in the field. With the advent of logging frameworks such as log4j, j.u.Logging, logback, and SLF4J, and then log aggregators that ingest loads of unstructured data into tools like Splunk, Datadog, and ElasticSearch/Kibana, you name it, there is confusion. People often conflate a log that outputs debug information line by line—which is undoubtedly useful—with addressing a different problem that's the one we aim to solve.

When I initially wrote the jPOS logger subsystem, large projects such as JBoss were looking for logging alternatives. I even had an email exchange with JBoss' author. He evaluated it but didn’t like it because it was too XMLish, which I found amusing since the whole JBoss configuration back in the day was heavily XML-based. Log4j was an early project hosted, if I recall correctly, at IBM’s alphaWorks, and that was his choice. Had I had that exchange a few weeks earlier, I would have adopted Log4j right away, as it was a promising project that proved to be the right way to go.

However, my concern and the focus of this post is not about the logger itself and its extensibility through SPIs, which are great. This post is about what one ends up putting in the log. It’s about the content and how to structure it in such a way that it becomes useful not only to the naked eye but also to other applications that ingest it.

In jPOS, it’s very common to encounter log events like the following:

<log realm="channel/186.48.107.208:58949" at="2024-04-29T13:06:13.086" lifespan="228ms">
  <receive>
    <isomsg direction="incoming">
      <!-- org.jpos.iso.packager.XMLPackager -->
      <field id="0" value="0800"/>
      <field id="11" value="000001"/>
      <field id="41" value="00000001"/>
      <field id="70" value="301"/>
    </isomsg>
  </receive>
</log>
<log realm="channel/186.48.107.208:58949" at="2024-04-29T13:06:13.618" lifespan="4ms">
  <send>
    <isomsg>
      <!-- org.jpos.iso.packager.XMLPackager -->
      <field id="0" value="0810"/>
      <field id="11" value="000001"/>
      <field id="37" value="743110"/>
      <field id="38" value="319046"/>
      <field id="39" value="0000"/>
      <field id="41" value="00000001"/>
      <field id="70" value="301"/>
    </isomsg>
  </send>
</log>

Now consider the following output:

2024-04-29 13:06:13.086 INFO Channel:23 - <log realm="channel/186.48.107.208:58949" at="2024-04-29T13:06:13.086" lifespan="228ms">
2024-04-29 13:06:13.086 INFO Channel:23 -   <receive>
2024-04-29 13:06:13.086 INFO Channel:23 -     <isomsg direction="incoming">
2024-04-29 13:06:13.086 INFO Channel:23 -       <!-- org.jpos.iso.packager.XMLPackager -->
2024-04-29 13:06:13.086 INFO Channel:23 -       <field id="0" value="0800"/>
2024-04-29 13:06:13.086 INFO Channel:23 -       <field id="11" value="000001"/>
2024-04-29 13:06:13.086 INFO Channel:23 -       <field id="41" value="00000001"/>
2024-04-29 13:06:13.086 INFO Channel:23 -       <field id="70" value="301"/>
2024-04-29 13:06:13.086 INFO Channel:23 -     </isomsg>
2024-04-29 13:06:13.086 INFO Channel:23 -   </receive>
2024-04-29 13:06:13.086 INFO Channel:23 - </log>
2024-04-29 13:06:13.086 INFO Channel:23 - <log realm="channel/186.48.107.208:58949" at="2024-04-29T13:06:13.618" lifespan="4ms">
2024-04-29 13:06:13.086 INFO Channel:23 -   <send>
2024-04-29 13:06:13.087 INFO Channel:23 -     <isomsg>
2024-04-29 13:06:13.087 INFO Channel:23 -       <!-- org.jpos.iso.packager.XMLPackager -->
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="0" value="0810"/>
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="11" value="000001"/>
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="37" value="743110"/>
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="38" value="319046"/>
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="39" value="0000"/>
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="41" value="00000001"/>
2024-04-29 13:06:13.087 INFO Channel:23 -       <field id="70" value="301"/>
2024-04-29 13:06:13.087 INFO Channel:23 -     </isomsg>
2024-04-29 13:06:13.087 INFO Channel:23 -   </send>
2024-04-29 13:06:13.087 INFO Channel:23 - </log>

This is actually a single log event and should go in a single log line. Frameworks support this, but most implementations I’ve seen in the wild, probably due to the fact that the event contains linefeeds, end up generating several dozen lines of logs, each with its own timestamp.

This output format presents several challenges:

1. Readability: The output is difficult to read and requires additional string manipulation to parse effectively, which complicates debugging and analysis. Yes, you can always use cut to take away the first chunk, but that's an extra step.
2. Excessive Detail: The granularity of timestamps down to milliseconds (e.g., 086 vs. 087) is unnecessary and consumes resources without adding value to the debug information.
3. Instance-Based Configuration Limitations: In jPOS, a single Channel class may connect to numerous endpoints as both a client and a server in multi-tenant applications. It's important to manage logs separately per instance, yet typical line loggers tie configuration to the class rather than to instances. You can, of course, use parameterized logger names, but that's not the standard way people tend to log information in their applications, and there's no standard approach for doing this, so different teams implement it in various ways.
4. Intermingling of Outputs: Line loggers mix outputs from multiple threads, necessitating the use of MDC (Mapped Diagnostic Context) to group together a logic log event. This approach increases code complexity and log verbosity.
5. Operational Inefficiency: Analyzing logs often involves navigating VPNs and two-factor authentication, complicating access to third-party log aggregator interfaces. This is reasonable for an operations team in charge of an application, but it presents quite a problem for external development teams trying to assist in case of issues.

The jPOS Structured Audit Log intends to improve the existing jPOS logging system by addressing some of its flaws and enhancing the original goals. It supports compact, structured output that is suitable for ingestion by log aggregators, while still retaining the capability for easy, text-based log manipulation for debugging and emergency situations.

AuditLogEvent​

To prevent conflicts with the existing system, we have introduced a new package named org.jpos.log, where this new feature is implemented. The main class within this package is AuditLogEvent. The intention is for AuditLogEvent to eventually replace the existing org.jpos.util.LogEvent.

The StructuredLogEvent is a very simple sealed interface:

public sealed interface AuditLogEvent permits ... { }

Q2 Start event​

When a jPOS log starts, we usually get the following XML preamble:

<log realm="Q2.system" at="2024-06-06T16:48:44.290350" lifespan="1ms">
  <info>
    Q2 started, deployDir=/opt/local/jpos/deploy, environment=default
  </info>
</log>

The equivalente structured audit log event is:

{
  "ts" : "2024-06-06T19:49:30.577151Z",
  "realm" : "Q2.system",
  "tag" : "info",
  "trace-id" : "dbd2e6b6-693a-4ff5-9c51-5b2b643a8c8d",
  "evts" : [ {
    "t" : "start",
    "ts" : "2024-06-06T19:49:30.576244Z",
    "q2" : "6969be9c-dce9-4919-ad7e-69b5faf1ef33",
    "version" : "3.0.0-SNAPSHOT",
    "deploy" : "/opt/local/jpos/deploy",
    "env" : "default"
  } ]
}

We aim to keep these log messages as short and compression-friendly as possible. Given that JSON is verbose, we want to avoid extra boilerplate, especially for transaction messages that are repeated sometimes hundreds of millions of times daily. Therefore, we prefer using readable abbreviations like ts for timestamp and tx for transmission, etc. Here, we are showing pretty-printed output; however, the actual output will be a compact one-liner. The encoding is assumed to be UTF-8.

Each JSON object needs to be easily unmarshalled by different applications. To distinguish between various types of messages, every SAL message includes a unique type property (abbreviated as t) to facilitate polymorphic deserialization.

In jPOS SAL, there are two types of audit log records:

1. jPOS native audit log records.
2. Application-specific audit log extensions (those that you can load via service loaders).

SAL Native audit log records are defined under the new org.jpos.log.evt package and are part of the AuditLogEvent sealed interface.

Application-specific audit log messages are loaded via the ServiceLoader (META-INF/services/org.jpos.log.AuditLogEvent).

The Start StructuredLogEvent is defined like this:

public record Start(Instant ts, UUID q2, String version, String appVersion, String deploy, String env) implements AuditLogEvent { }

• clazz is the logger’s class (i.e. DailyLogListener)
• q2 is Q2’s instance Id
• version is Q2’s version
• appVersion is the application’s version

Q2 Stop event​

Instead of the old </logger> closing element, we'll have an end JSON event

The Stop AuditLogEvent is defined as:

public record Stop(Instant ts, UUID id, Duration uptime) implements AuditLogEvent { }

The JSON output lookw like this:

{
  "ts" : "2024-06-06T19:49:38.050499Z",
  "realm" : "Q2.system",
  "tag" : "info",
  "trace-id" : "446c7ed1-ba61-4f5c-9f13-3edf1699242f",
  "evts" : [ {
    "t" : "stop",
    "ts" : "2024-06-06T19:49:38.050480Z",
    "id" : "6969be9c-dce9-4919-ad7e-69b5faf1ef33",
    "uptime" : 7.827676000
  } ]
}

LogWriters, LogRenderers, AuditLogEvents​

jPOS users are familiar with channels, packagers, and ISOMsgs, and there's an analogy between these components.

An AuditLogEvent is analogous to an ISOMsg. It is an object that encapsulates information.

The LogRenderer functions like a packager. It converts the AuditLogEvent into a wire format. Just as you can have multiple packagers to handle different ISO-8583 variants, you can have multiple LogRenderers to convert AuditLogEvents into different formats.

We currently handle four formats:

• TXT: A new format suitable for injection into regular line loggers.
• XML: Equivalent to the existing format.
• JSON: As shown in the examples above.
• MARKDOWN: Suitable for use during development/tests or for rendering in web-based UIs.

Finally, the LogWriter is like the channel, it's the one in charge to output the already rendered AuditLogEvent to the log PrintStream.

LogWriter​

The LogWriter interface, contributed by Alwyn not so long ago, is a great addition. It plugs into a LogListener and is very easy to configure:

<log-listener class="org.jpos.util.SimpleLogListener" enabled="true">
    <writer class="org.jpos.util.JsonLogWriter" enabled="true" />
</log-listener>

If we do not specify a writer, the log listener behaves like the traditional jPOS. It outputs all Loggeable objects using their dump method. We have JsonLogWriter, MarkdownLogWriter, TxtLogWriter, and XmlLogWriter.

LogRenderer​

The LogRenderers interface looks like this:

public interface LogRenderer<T> {
    void render (T obj, PrintStream ps, String indent);
    Class<?> clazz();
    Type type();
    ...
    ...
}

The renderers are then loaded via the org.jpos.log.LogRenderer service loader that looks like this:

org.jpos.log.render.json.LogEventJsonLogRenderer
org.jpos.log.render.json.LoggeableJsonLogRenderer
org.jpos.log.render.json.AuditLogEventJsonLogRenderer

org.jpos.log.render.xml.LoggeableXmlLogRenderer

org.jpos.log.render.markdown.ProfilerMarkdownRenderer
org.jpos.log.render.markdown.ContextMarkdownRenderer
org.jpos.log.render.markdown.LoggeableMarkdownLogRenderer
org.jpos.log.render.markdown.LogEventMarkdownRenderer
org.jpos.log.render.markdown.StringMarkdownLogRenderer
org.jpos.log.render.markdown.ObjectMarkdownLogRenderer
org.jpos.log.render.markdown.ByteArrayMarkdownLogRenderer
org.jpos.log.render.markdown.ThrowableMarkdownLogRenderer
org.jpos.log.render.markdown.ElementMarkdownLogRenderer
org.jpos.log.render.markdown.TransactionManagerTraceMarkdownLogRenderer
org.jpos.log.render.markdown.TransactionManagerTraceArrayMarkdownLogRenderer
...
...

There's a handy LogRendererRegistry that can get you a renderer for any given object. It properly traverses the class hierarchy and implementation hierarchy to get the most suitable renderer for an object if one is not defined for a given class. Because that reflection-based traversal is expensive, all results are cached and readily available for the next call.

Renderer implementations are very easy to write, and we encourage users to create specific ones for their objects. We aim to provide a large number of renderers for jPOS objects. Here is an example of a ByteArray renderer that produces Markdown output:

public final class ByteArrayMarkdownLogRenderer implements LogRenderer<byte[]> {
    @Override
    public void render(byte[] b, PrintStream ps, String indent) {
        if (b.length > 16) {
            ps.printf ("```%n%s%n```%n", indent(indent, ISOUtil.hexdump(b)));
        } else {
            ps.printf ("`%s`%n", indent(indent,ISOUtil.hexString(b)));
        }
    }
    public Class<?> clazz() {
        return byte[].class;
    }
    public Type type() {
        return Type.MARKDOWN;
    }
}

This is a just-for-fun proof of concept that outputs a jPOS profiler as a Markdown table:

public final class ProfilerMarkdownRenderer implements LogRenderer<Profiler> {
    public ProfilerMarkdownRenderer() {
    }

    @Override
    public void render(Profiler prof, PrintStream ps, String indent) {
        var events = prof.getEvents();
        int width = maxLength(events.keySet());
        final String fmt = STR."| %-\{width}s | %10.10s | %10.10s |%n";
        ps.print (row(fmt, "Checkpoint", "Elapsed", "Total"));
        ps.print(
          row(fmt, "-".repeat(width), "---------:", "-------:")
        );
        StringBuilder graph = new StringBuilder();
        events.forEach((key, v) -> {
            ps.print(
              row(fmt, v.getEventName(), toMillis(v.getDurationInNanos()), toMillis(v.getTotalDurationInNanos()))
            );
            graph.append ("  \"%s\" : %s%n".formatted(key, toMillis(v.getDurationInNanos())));
        });
        ps.println();
        ps.println ("```mermaid");
        ps.println ("pie title Profiler");
        ps.println (graph);
        ps.println ("```");

    }
    public Class<?> clazz() {
        return Profiler.class;
    }

    public Type type() {
        return Type.MARKDOWN;
    }
    private String row (String fmt, String c1, String c2, String c3) {
        return fmt.formatted(c1, c2, c3);
    }
    private String toString(Profiler.Entry e, String fmt) {
        return FMT."""
          \{fmt}s |\{toMillis(e.getDurationInNanos())} | \{toMillis(e.getTotalDurationInNanos())} |
          """.formatted(e.getEventName());
    }

    private String toMillis(long nanos) {
        return FMT."%d\{nanos / Profiler.TO_MILLIS}.%03d\{nanos % Profiler.TO_MILLIS % 1000}";
    }

    private int maxLength (Set<String> keys) {
        return keys.stream()
          .mapToInt(String::length)
          .max()
          .orElse(0); // R
    }
}

With the previous renderer, the regular profiler output:

    <profiler>
      prepare: o.j.t.p.Debug [8.8/8.8]
      prepare: o.j.t.p.Debug-1 [0.7/9.6]
      prepare: o.j.t.p.Delay [2.4/12.0]
      prepare: o.j.t.p.Trace [0.6/12.7]
       commit: o.j.t.p.Debug [1.9/14.7]
       commit: o.j.t.p.Debug-1 [0.4/15.1]
       commit: o.j.t.p.Delay [0.4/15.6]
       commit: o.j.t.p.Trace [0.5/16.1]
      end [7.6/23.7]
    </profiler>

Looks like this:

Recap on why we are doing this​

People often use Grok, Fluentd, Splunk regexp-based filters, or just grep/AWK manipulation to make sense of log messages produced by applications. These applications sometimes decide to change the message format from:

Starting

to:

 ____  _             _   _             
/ ___|| |_ __ _ _ __| |_(_)_ __   __ _ 
\___ \| __/ _` | '__| __| | '_ \ / _` |
 ___) | || (_| | |  | |_| | | | | (_| |
|____/ \__\__,_|_|   \__|_|_| |_|\__, |
                                 |___/ 

Because banners are cool, they inadvertently trick those regexps with an innocent change.

We want jPOS audit logs to be precise, compact, and suitable for storage (e.g., in jPOS' binlog) for audit purposes

Stay tuned as this is coming soon to jPOS next.

jPOS configuration is very flexible, but that flexibility can sometimes lead to confusion.

We have two main categories:

• Build-time static token replacement (jPOS build target).
• Runtime environments.

Build-time static token replacement​

This is described in detail in the Configuration Tutorial, but the basic idea is that at build time, when you call gradle installApp or gradle dist, you have the ability to define a compile-time target.

The default target is called devel and reads an optional property file called devel.properties.

If your devel.properties file looks like this:

ABC=AlphaBravoCharlie

And then you have a QBean configuration like this:

<property name="ABC" value="@ABC@" />

The @ABC@ will be expanded to AlphaBravoCharlie in the final file that will land in the build directory.

If you go to build/install/xxx/deploy/yourxml.xml, you’ll see something like this:

<property name="ABC" value="AlphaBravoCharlie" />

The jPOS build system performs that replacement in XML files in the deploy directory, as well as in configuration files (.cfg, .properties) in the cfg directory.

A typical use case, very useful during development is to define a database name.

You can have a devel.properties file with tokens like this:

dbhost=localhost
dbname=jposee
dbuser=jpos
dbpass=password
dbport=5432

And then have a db.properties file (in src/dist/cfg/db.properties) that looks like this:

connection.url=jdbc:postgresql://@dbhost@:@dbport@/@dbname@

When you call gradle installApp, you’ll see that the destination db.properties file in the build/install/xxx/cfg directory will look something like this:

connection.url=jdbc:postgresql://localhost:5432/jpos

When you run locally, in development mode, your devel.properties file, which happens to be the default one, is the one providing tokens for replacement.

But you can call gradle -Ptarget=ci installApp. In that case, tokens get read from a file called ci.properties that you can use in your continuous integration environment.

Runtime Environments​

The runtime environments are explained here, but the basic idea is that you can define a variable either in a YAML file, a Java property, or an OS environment variable and use it as part of the configuration using property expansion. Imagine you have an OS environment variable like this:

export DB_PASSWORD=mysupersecurepassword

Then you can configure a QBean, or config file with something like:

<property name="dbpass" value="${db.password}" />

When you call cfg.get("dbpass") from your QBean or participant implementation, you will get the string "mysupersecurepassword".

There are variations you can use, such as defaults like ${db.password:nopassword}, in which case, if the DB_PASSWORD OS environment variable is not available or not exported, a call to cfg.get("dbpass") would return nopassword.

Things start to get confusing when we hit Config Smell 2:

CONFIG SMELL 2

We often encounter situations where a build-time target configuration looks like this:

dbpass=${db.password}

and then the dbpass property in a given QBean or configuration file looks like this:

<property name="dbpass" value="@dbpass@" />

That totally works. The resulting file in the build directory after a gradle installApp will look like this:

<property name="dbpass" value="${db.password}" />

as we want, and then, at runtime, the ${db.password} value will be de-referenced using the DB_PASSWORD environment variable.

That's fine, everything works, but why oh why!

When you see a target build time configured like this, new users might get confused about when the ${db.password} gets de-referenced—whether it happens at build time based on the build-time environment variable or at runtime. It’s very confusing, and even an experienced jPOS developer can get caught off guard. Don’t do it.

We mentioned CODE SMELL 1 and CODE SMELL 2, but there’s CODE SMELL 0!:

I've recently embarked on an ambitious project to develop a new jPOS documentation, which is currently in its nascent stages. This tutorial is designed to evolve in tandem with ongoing jPOS development, and in time, it will replace existing documentation to become a dynamic, live tutorial and reference.

As it stands, the tutorial is in its early stages, but it already offers valuable insights for newcomers to jPOS, particularly with the setup primer and QBean information. Veterans of jPOS will find the sections on 'Environments' insightful, especially for applications in cloud deployments. This is also a prime opportunity to test and experience the jPOS Gradle Plugin in action.

Alongside the tutorial, we have a companion project on Github. It’s structured with distinct branches for each part of the tutorial, enabling you to access and execute the examples easily.

Since this is a work in progress and will be evolving alongside jPOS, your feedback is incredibly valuable. We encourage you to share your thoughts, suggestions, and insights, which will be instrumental in shaping this tutorial into a comprehensive and up-to-date resource for all things jPOS.

Here is the link.

The jPOS TransactionManager context, when it comes to traverse all participants, is quite promiscuous, as promiscuous as the global state of any application. It relies on the participants to do the right thing and don't step over each other, by mistake, or on purpose.

As applications grow and we move from a handful participants to several dozens, or even hundreds, it becomes very useful to put some constraints on what a participant can or can't do related to its Context.

On large jPOS applications, created by disparate teams, the TransactionManager configuration file is usually an excellent self-documenting starting point in order to figure out which transactions are supported, which participants are involved and how they are configured.

In addition, it is common for a participant’s implementation, before doing its job, to check for the presence in the Context of its needed input variables. CheckFields for example, needs a REQUEST object. SendResponse, needs a RESPONSE object.

To solve this, we've introduced a new required element, verified by the TransactionManager before calling the participant's prepare method, that looks like this:

<participant class="org.jpos.transaction.CheckFields">
  <requires>REQUEST</requires>
</participant>

In this case, the TM checks for the presence of a REQUEST entry in the Context. If it’s not present, the transaction aborts right away (as if the participant had returned ABORTED).

This is just syntactic sugar, as the participant can check (and actually check) that, but there's a little twist.

The participant does not receive the whole context, it just receives a clone of it with JUST the entries described in the <require> element (which BTW, can be a comma separated list).

In addition to the require element, we support an optional element. i.e.:

<participant class="org.jpos.transaction.CheckFields">
  <requires>REQUEST</requires>
  <optional>TIMESTAMP, TIMEZONE</optional>
</participant>

You get the idea, if the optional TIMESTAMP and TIMEZONE entries are present, they would get copied to the mini Context used to call the participant.

A similar approach is used in order to selectively get the output of a participant. We use the provides element like this:

<participant class="org.jpos.transaction.CreateDSRequest">
  <requires>REQUEST</requires>
  <provides>RESPONSE</provides>
</participant>

The TransactionManager, who has access to both the original Context and the miniContext offered to the participant, merges back ONLY the entries listed in the provides method.

This is an experimental preview feature implemented in jPOS 3.0 (next). It needs to be battle tested in order to see if it makes sense to keep it, or it's just a useless idea. If we like it, and we continue supporting it, we may choose to enforce it on every participant. In a second phase we can define a TM-level promiscuousproperty so that if one chooses the old behavior, you need to set it true, either globally at the TM config level, or at the participant level, perhaps with a promiscuous="true" attribute.

jPOS 2.1.8 has been released. New development version is 2.1.9-SNAPSHOT and jPOS 3.0.0 (aka 'next').

See ChangeLog for details.

We will continue to maintain the 2.x.x series for a long while, so you can consider the 2.x.x series an LTS version, but all the fun and new features will happen in 3.x.x.

Typical jPOS applications have many similar servers, muxes, and channels. Sometimes hundreds of them.

In order to simplify its configuration Q2 now supports templates that can be launched from a template deployer, or programmatically using Q2's deployTemplate method.

A template is identical to a regular QBean XML descriptor, and can be placed anywhere in the filesystem, or classpath (including dynamic classpath) that has a special keyword called __PREFIX__ that are replaced at deploy time.

Q2's deployTemplate method has the following signature:

deployTemplate(String resource, String filename, String prefix);

• resource is the resource location (e.g.: templates/channel.xml). If the resource starts with jar:, Q2 fetchs it from the classpath (e.g.: jar:META-INF/q2/templates/channel.xml).
• filename is the QBean descriptor filename, e.g.: 10_acme_channel.xml
• prefix is the Environment prefix (see below).

Imagine you have an environment (cfg/default.yml) file that looks like this:

    acme:
        host: 192.168.1.1
        port: 8000
    emca:
        host: 192.168.1.2
        port: 8001

In a regular deployment, you could have two channel configurations like this:

    10_channel_acme.xml
    
    <channel-adaptor name="acme-channel-adaptor" ...>
      <channel class="${acme.channel}" packager=...>
        <property name="host" value="${acme.host}" />
        <property name="port" value="${acme.port}" />
        ...
        ...
      </channel>
      <in>acme-send</in>
      <out>acme-receive</out>
    </channel-adaptor>
    
    10_channel_emca.xml
    
    <channel-adaptor name="emca-channel-adaptor" ...>
      <channel class="${emca.channel}" packager=...>
        <property name="host" value="${emca.host}" />
        <property name="port" value="${emca.port}" />
        ...
        ...
      </channel>
      <in>emca-send</in>
      <out>emca-receive</out>
    </channel-adaptor>

With templates, you can have a single template like this somewhere in your filesystem or classpath (say templates/channel.xml).

<channel-adaptor name="__PREFIX__-channel-adaptor" 
    enabled="${__PREFIX__.enabled:false}"
    class="org.jpos.q2.iso.ChannelAdaptor" 
    logger="${__PREFIX__.logger:Q2}">
 <channel class="${__PREFIX__.channel}" 
         logger="${__PREFIX__.logger:Q2}" 
       packager="${__PREFIX__.packager:org.jpos.iso.packager.GenericPackager}">
  <property name="host" value="${__PREFIX__.host}" />
  <property name="port" value="${__PREFIX__.port}" />
  <property name="header" value="${__PREFIX__.header}" />
  <property name="connect-timeout" value="${__PREFIX__.timeout:5000}" />
  <property name="packager-config" value="${__PREFIX__.packagerConfig}" />
 </channel>
 <in>__PREFIX__-send</in>
 <out>__PREFIX__-receive</out>
 <reconnect-delay>${__PREFIX__.reconnect:10000}</reconnect-delay>
 <wait-for-workers-on-stop>${__PREFIX__.wait:yes}</wait-for-workers-on-stop>
</channel-adaptor>

and perhaps a mux.xml connected to it:

----
<mux name="__PREFIX__" class="org.jpos.q2.iso.QMUX" 
    enabled="${__PREFIX__.enabled:false}"
    logger="${__PREFIX__.logger:Q2}" realm="__PREFIX__">
  <key>${__PREFIX__.mux.key:41,11}</key>

 <in>__PREFIX__-receive</in>
 <out>__PREFIX__-send</out>

 <ready>__PREFIX__-channel.ready</ready>
</mux>
----

Then you can deploy a QBean descriptor like this:

<templates>
    <template resource="templates/channel.xml" descriptor-prefix="10_channel_">
        acme,emca
    </template>
    <template resource="templates/mux.xml" descriptor-prefix="20_mux_">
        acme,emca
    </template>
</templates>

The special text __PREFIX__ is replaced by Q2 in each file using the prefix acme and emca, so the properties:

  <property name="host" value="${__PREFIX__.host}" />
  <property name="port" value="${__PREFIX__.port}" />

gets converted to

  <property name="host" value="${acme.host}" />
  <property name="port" value="${acme.port}" />

Very simple, it's just configuration sugar, but comes very handy in deployments with hundreds of services.

This is available in jPOS Next (series 3.x.x) starting in 3.0.0-SNAPSHOT availble in jPOS Maven repo, as well as Github next branch.