Guide‎ > ‎

Logic Debugging

Much as we love spreadsheets and all they represent, they do have two challenges:

  1. What is it supposed to do?
    We have all gotten a spreadsheet and wondered what it was supposed to do. For Business Logic, see Logicdoc.
  2. What is it doing?
    Our favorite question, for spreadsheets in particular and software in general. This document describes Business Logic services for you to understand what is (or is not) happening, and how to fix it.



Testing with JUnit

This section suggests a JUnit-based process for testing Business Logic, integrated into the Logicdoc process for gathering Requirements and providing logic traceability.

JUnit test

There are many levels of tests, but surely one is to save a transaction and check the database to assure the results are expected. A significant portion of our product was tested in this manner.

Creating a JUnit test is a standard procedure, unaffected by Business Logic. Please consult your documentation and team standards.


SnapshotDB - database result checking

Checking the results is also a well-known problem. To facilitate this, we offer a simple tool called SnapshotDB, used as follows:

  1. Before test runs
    • create a new SnapshotDB()
    • this reads all the database rows into memory
  2. After test completes
    • invoke snapshot.changes("title")
      this compares old/current values, and prints them out
    • invoke snapshot.assertChanged("expected change")
      this asserts an expected change, throwing a stacktrace to terminate JUnit

Here is a short sample of use. You can find more by reviewing the examples shipped with the product:

		SnapShotDB snapShot = new SnapShotDB(staticFactory)

		session = staticFactory.getCurrentSession();
		tx = session.beginTransaction()

		purchaseOrder = session.get (Purchaseorder.class, 1L)
		purchaseOrder.isReady = true
		LogicContext.setCurrentUseCaseName (tx, "Purchaseorder_update_makeReady_test")
		session.update (purchaseOrder)
		tx.commit(); 

		String dbChanges = snapShot.changes(title)
		snapShot.assertChanged("Customer[Gloria's Garden]: balance += 50.0000")
		snapShot.assertChanged("Product[1]: totalQtyOrdered += 1")
		snapShot.assertChanged("Product[2]: totalQtyOrdered += 2")

SnapshotDB is not a formal part of the product:

  1. It is distributed for your use without support, and includes source
  2. Because it reads all rows into memory, it is not appropriate for anything except very small databases, containing at most a few hundred rows.

Logicdoc integration

It is good practice to be clear on the mappings between tests and PURL Use Case Classes. There are many alternatives. 

You can keep your Use Case Classes separate from your tests.  In BusLogicIntro, we cross referenced our Use Cases/Requirements and tests as shown in the high-lighted lines below:

  1. The upper window is a JUnit test class
    • It creates a Logicdoc instance. This is for documentation only, but it is very useful to jump to the Logicdoc Use Case Class (eg, F3 in Eclipse), which here is in the lower window

  2. The lower window is a Logicdoc Use Case Class

Another alternative is to combine your tests and Use Case / Requirements into classes that express both.  This approach is demonstrated in BusLogicDemo - see its Logicdoc here.


Logging

As with general Java, most of your logic is debugged by addressing stack traces, and by reviewing the log. For more complex issues, employ Debugging services, below.

Like Hibernate, Business Logic uses log4j. In conjunction with Hiberate logging, the standard console log will reveal every SQL command and every rule that fires (see Log Output).


Logging Configuration

Use the log4j.properties file to configure the logging. Since the package structure reveals detail that is needless and confusing, the system logs through a small number of loggers, for which the defaults are shown below:


#########################################

# ABL logging


log4j.logger.abl=debug

#log4j.logger.abl.depend=warn

#log4j.logger.abl.persis=warn

#log4j.logger.abl.engine=warn

#log4j.logger.abl.evtlst=warn

#log4j.logger.abl.recomp=warn

#log4j.logger.abl.sysdbg=warn


Log Level: Info vs. Debug

Since 2.20, you can control the amount of log output by using log4j.logger.abl=info instead of debug.  Info produces fewer rows (one per processed row, vs. one for each rule), and shorter rows (unchanged attributes are not shown).



Log Output

The screen shot below shows a typical log from the Make Order Ready test. Notes:

  1. Forward Chaining nest level indentation
    The indentation depicts the cascade/adjustment forward chaining, enabling you to skip over portions of the log as needed.
  2. Reporting Domain Object
    The bracketed string identifies the Business Logic Component reporting the log entry, and how it was called. For example, [Lineitem CASCADED via lineitems] means
    • Lineitem is reporting
    • Lineitem was invoked due to a cascade via Purchaseorder.lineitems (the class/accessor through which the cascade is occurring)
      • Note: USER means the logic was invoked due to a user (Hibernate caller) update
  3. Message
    The next string is the message (e.g., what logic is being executed), as further described below
  4. Domain Object
    The toString of the Domain Object is appended to each log entry (including old values where applicable). This information provides significant insight into the why the logic execution produced the result shown.  Since 2.20, altered attributes are grouped to the front, to make changes easier to spot.


Salient log Messages:
  1. Adjust - child adjusting parent
    An entry such as Adjusting summed attribute: balance+=50.0000 signifies that a child is adjusting a parents sum/count. After all the adjustments are complete for a given parent, you will see an indentation as the system then invokes the parent logic (i.e., a Forward Chain)
  2. Cascade
    An entry such as .. cascading to child ...lineitems signifies that a parent is cascading a changed Parent Reference value to child rows. This will be followed by an indentation as the system then invokes the child logic (i.e., a Forward Chain)
  3. Formula
    An entry such as ==> Formula changes: isReady reflects the execution of a formula that changed the derived value.
    • Note: no log entry is made if the value did not change.
  4. Action
    An entry such as Action(actionClonePurchaseorder) invoking on means that an action event is firing
  5. Checking - these simply confirm the phases of logic execution, and frequently are useful in interpreting ensuing entries 

Log Analysis

The BusLogicIntro test test/buslogicintrotest/orderentry/update/Purchaseorder_update_makeReady_test.groovy (see Make Order Ready ) provides a good example of a typical transaction.  We are setting the isReady flag to true in a Purchaseorder valued at $50 with 2 Lineitems (1 ProductId=1 @ $10, and 2 ProductId=2 @ 20).

Our requirements are to (click the thumbnail at right to see the database structure):
  1. reduce the Customer's balance, and 
  2. adjust the Products' totalQtyOrdered for each lineitem in the order
This log is a illustration of Forward Chaining:
  1. USER Update of Purchaseorder initiates the logic
    1. Cascade occurs since Lineitem.isReady derived as lineitem.puchaseorder.isReady
      This is a Parent Reference. Changes to such fields initiate Cascade to child objects to run their logic (Forward Chain)
      1. Adjust occurs since Product.totalQtyOrdered = sum(lineitems.qtyOrdered where isReady
        Changes to the child summed attribute or qualification condition (as in this case) trigger adjustment
  2. After forward chaining, the Purchaseorder logic completes
  3. After all USER submissions are processed, Commit logic is executed


Debugging

You can set breakpoints in your Business Logic, and inspect the system state during Logic execution. In the screen shot below, note:

  1. We have set a breakpoint in the derivation rule for isReady in LineitemLogic
    • This is a Java logic file; the exact same procedure works for Groovy
  2. The log (bottom) is useful understanding how you got here (in addition to the Debug stack on the upper left)
  3. The Variables view (upper right) provides valuable information about Domain Objects and the Transaction Context

You can now utilize the services of your Interactive Development Environment (e.g., Eclipse (TM)) to alter variables, step and so forth. Important points:

  1. Your formula may be skipped due to pruning


Debugging and Proxies

Hibernate often builds Proxies for your Domain Objects.  The diagram at the right shows that these are identified by the javassist portion in the name.

You will notice that such proxies do not show variable values for the attributes (e.g., balance shows null).  When this occurs:
  1. though not the case in the large diagram to the right, you may first need to open a value object as shown in the tumbnail (click for full display)

  2. open the handler item, and then

  3. open target within that.  
As shown at the right, the values are then available.

Note: Automated Business Logic also builds proxies. However, these will show the attribute values when you click the entity variable.
 


Graphical Debugging

You can also debug logic execution graphically.  Recall the logic engine provides events during logic execution.   The MindMapListener subscribes to these, and produces a file you can open with with FreePlane, and examine your logic execution as shown below:



MindMapListener can run in alternate mechanisms as described in the the sub-sections below.


By Configuration

As shown below:
  1. Engage MindMapListener as a Logic Listener with an entry in ABLConfig.properties
  2. Configure MindMapListener with a MindMapListener.properties
As shown below, you can configure:
  1. A semi-colon list of filters.  Only transactions where any output line matches the filter result in file creation
  2. The output directory.  Files are created here, one for each transaction matching the filter, with a numeric suffix to avoid collisions



By Explicit Call

You can call the explicit constructor below as shown in the top window for class Purchaseorder_update_makeReady_test.  This will generate an output file named after your calling class (Purchaseorder_update_makeReady_test.mm) in the logs folder.





Comments