Dr. Debug's Advice

Dear fellow Debuggers,

Last week I came accross an interesting issue and I thought I would share my findings with you.

In BPM version 8.5.5 the new Client-Side Human Service (CSHS) was introduced.
In a fairly simple usecase, we had a CSHS with a Coach, and that Coach basically had 2 buttons - Button A and Button B. Each button had a certain value assigned to a variable. Upon a click of the button, the value of this variable was changed in a Client-Side Script using Javascript. We then ran a service (General System Service) to throw a validation error. The following picture will give you an idea of the whole scenario:

The Service looked like this:

It is important to understand, that the validation step was a script named "Validation Script" by the user. The validation service has a green icon (V) leading to the script step. If you don't see it, this is just a regular script step (not true validation). See this Knowledge Center link.

From the Knowledge Center:

Please note the green checkmarks or Vs.

However, to configure this validation service, you would have to set the "fire validation property" to "before" for the line to the boundary event. But the CSHS does not support this kind of validation. This is only available for Heritage Coaches in v8.5.5.
 

In our usecase, when we clicked the button the values of the variables should have been changed when the validation error was triggered, however, the variables still showed the "old" values.

So why was that?

Well, in v8.5.5 for the CSHS, when validation errors occur, ONLY the validation errors info is returned back to Coach for display. Any changed variables are NOT returned to the Coach. This explains why our variables showed the old values, and not the ones we assigned to them in our Client-Side Script.
Note that this behavior will be enhanced in v8.5.6 where both validation errors AND changed variables are to be returned.

With this in mind, we can now understand why our variables remained unchanged.
And if this does not help, take two of these  and call me in the morning.

Yours
Doc D.

G'day Folks,

Yesterday I came across an interesting issue. 

After upgrading from BPM v7.5.1.0 to v7.5.1.2 the Server List in my Process Center was completely empty. The servers were reachable and available though.

When I clicked the Servers tab, I found the following exception in the log:

[3/11/15 12:16:12:430 GMT+01:00] 00000061 wle  E   CWLLG1274E:   An exception occurred.
java.lang.RuntimeException: Unable to  locate initialization vector and encrypted data
at com.lombardisoftware.utility.CipherHelper.decrypt(CipherHelper.java: 84)
at com.lombardisoftware.client.persistence.Server.getDecryptedPassword (Server.java:57)
at com.lombardisoftware.repository.server.ObjectManagementServiceImpl.fromServer(ObjectManagementServiceImpl.java:1966)
at com.lombardisoftware.repository.server.ObjectManagementServiceImpl.getServers(ObjectManagementServiceImpl.java:777)
[...]

I looked at the LSW_SERVER table of my BPM database and the server entries were listed.

My first thought was that I was hitting APAR JR42774 - as described in this Technote.
However, a look at the 7.5.1.2 fixlist showed the iFix for this APAR is included in 7.5.1.2.

Reviewing the table definition of my LSW_SERVER table, I saw that the password column had a definition of varchar(256), although after the installation of FP2 (or JR42774) it was supposed to have varchar(1000). So something must have went wrong during the installation of the fixpack - most likely during the post-install steps where the db schema was upgraded.

After I updated the schema (as described in the post install steps) I nulled the passwords in the LSW_SERVER table, as the heartbeat would simply re-add them afterwards. 
And voilá - the servers were listed again.

And if you are facing the same issue but the above steps do not help, take two of these and call me in the morning.
Your Doc D.

Dear fellow Debuggers,

The other day I ran into a problem, where my IBM Integration Designer (IID) did not start properly. I tried to start the application, but the startup never finished and was hung. Frozen - no way to stop it except killing the process. Alternatively I could have waited for it to crash..

If it does crash during the workspace initialization phase, a log file is written to the workspace/.metadata/ directory. The file is named ".log" and is always worth a look. In my case, I saw the following exception:

!ENTRY org.eclipse.osgi 2 0 2015

!MESSAGE While loading class "org.eclipse.core.runtime.RegistryFactory", thread "Thread[Start Level Event Dispatcher,5,main]" timed out waiting (5000ms) for thread "Thread[Component Resolve Thread,5,main]" to finish starting bundle "org.eclipse.equinox.registry_3.5.0.v20100503 [5910]". To avoid deadlock, thread "Thread[Start Level Event Dispatcher,5,main]" is proceeding but "org.eclipse.core.runtime.RegistryFactory" may not be fully initialized.

!STACK 0

org.osgi.framework.BundleException: State change in progress for bundle "reference:file:/C:/IBM/SDPShared/plugins/org.eclipse.equinox.registry_3.5.0.v20100503.jar" by thread "Component Resolve Thread".

                at org.eclipse.osgi.framework.internal.core.AbstractBundle.beginStateChange(AbstractBundle.java:1077)

                at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:282)

                at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:417)

This output points towards an issue with the equinox registry.

If it do Org.eclipse.equinox.registry is one of the first eclipse plugins started and usually indicates that a bundle was not loaded properly.
So how can we debug this further?

1. Create a simple file in any text editor of your choice and name it ".options" (without the quotes).
    
2. Copy/paste the following content into this file:
   

   /debug = true
   org.eclipse.ui/debug = true
   org.eclipse.core.runtime/debug = true
   org.eclipse.ui/trace/graphics = true 
   
   

3. Save your changes to the .options file
    

4. Place the .options file into the IID root directory where the eclipse.exe resides
    

5. Open a command line window and start IID using the following one-liner:
    

   C:\IBM\IID\v8.5\eclipsec.exe -product com.ibm.wbit.feature.ide -debug -consolelog -vm C:\IBM\IID\v8.5\jdk\jre\bin\java.exe -Xquickstart -Xms512m-Xmx1024m -Xmnx64m -Xgcpolicy:gencon -Xscmx96m -Xshareclasses:name=none,nonfatal -XX:MaxPermSize=512M -Xverify:none -Declipse.p2.verifyPlan=false -cp C:\:\IBM\IID\v8.5\plugins\org.eclipse.equinox.launcher_1.1.1.R36x_v20101122_1400.jar org.eclipse.equinox.launcher.Main -debug -product com.ibm.wbit.feature.ide > IID_debug.log 2>&1 
    

6. This will generate an additional IID_debug.log file in your <IID_install_root> directory. Review this log for further clues.

In my case, a simple restart of my machine and then starting IID with the -clean option resolved the error.

A pretty cool overview over the available Eclipse debug strings can be found here.

And if nothing helps, take two of these  and call me in the morning.

Yours,
Dr. D

Good morning friends of the hands-on debugging,

Some of you may have already encountered such a situation. You get your morning coffee, boot up your workstation, you start your IBM Integration Designer (IID) and bang - there it is. A crash notification. What a good start in your day.
Right after you started the application, it crashes and presents you an Eclipse pop-up window like the following:

Java was started but returned exit code=1 

If you have not encountered this yet - Congratulations! I would still recommend reading this post, maybe some days you will need this .

So, what's next?

Step 1: Prepare yourself for some debug fun. If your coffee is gone, I recommend getting another one, then continuing with the below steps. If you still have coffee left, move right on to the next step.

Step 2: Did this installation ever work or did you just install it? If this error shows up after a new installation of the Eclipse based product (here IID), check out the installation logs to make sure it was installed without any exceptions. To do so, have a look at the IBM Installation Manager log files under <Installation_Manager_Install_Dir>/logs

In my case:

Open the index.xml file and review all logs linked in there for any exceptions or failures during the installation.

Failed or partially failed installations may cause such statup issues.

Step 3: Did anybody mess with your Eclipse startup parameters? If this is not a new installation and the exception happened all of a sudden, maybe some JVM arguments were changed and are hence causing this crash. Always a good candidate is the -Xmx value, which specifies the maximum memory allocation pool for the Java Virtual Machine (JVM). A lot of users still think: The more, the better! Unfortunately they overtune the JVM and the memory allocation is simply too large for the JVM to be successfully created. If changes were made to the JVM settings, please revert those changes back to the default values (you can for example compare them to a working or untouched system). Then try to launch your Eclipse based application again.

Step 4: Create Javacore log files to gain more insight into the root cause of the crash. As Eclipse is still in the start-up process when the crash occurs, the JVM errors cannot be written to the Eclipse error logs under <workspace_root>/.metadata/.log
Hence we need another way to get more information about the root cause. Open your eclipse.ini file (located in the <install_root> directory) and add the following line under -vmargs opt:

-Xdump:java:events=vmstop

This should enforce the creation of a javacore.txt file in case of a JVM crash. In our case here, you will find it in the IID root directory after the next restart.

And if nothing helps, take two of these and call me in the morning.

Your Dr. D

Or you can reload this page, grap the HAR from your browser console and it might look something like this:

And if none of this helps, take two of these and call me in the morning.

Good morning friends,

Today I would like to show you, how you can set a specific editor to display a certain file type.

As you all may already know, the IBM Integration Designer (IID) is a development tool where you can use a Graphical User Interface to create and test your applications. For this GUI there is a set of editors available that will display your artifacts in a graphical view instead of a file view.

An example would be the mediation flow, which is opened with the "Mediation Flow Editor" by default when you open the flow.

So, you may run into situations where the view is not available, so the mediation flow might open in the XML file view. First attempt would be to open it from the context menu (BI view >> right click on your mediation flow name >> Open With >> Mediation Flow Editor). If you are as unlucky as I am, this option is not available, and the context menu looks like this:

How can I get my Mediation Flow Editor back? Well, it's not hard if you know how. And I am going to show you how.

All you need to do is to register the editor for the related file type again. In our case the mediation flow (associated to the .mfc file type).

To do so, click on Window >> Preferences and click on the little eraser icon to remove all filters.

Then click on General >> Editors >> File Associations 

You will find a list of file types where you can associate the correct editor to the according selected file type.

In our example, we will select the file type .mfc. You will now see the editors in the "Associated editors" section. With the "Add..." button we can now add additional editors for this file type. And we will now add the 'Mediation Flow Editor".

All we need to do now is save our changed and go back to the BI view where we will open the context menu to verify the Mediation Flow Editor was added:

And we're there. It worked.

And if all of that does not help, take two of these  and call me in the morning.

Your Doc D.

Dearest Debuggers,

Last week I stumbled across an interesting question in BPM. As it took me some time to figure out why BPM was behaving the way it did, I thouhgt I'd share my findings with you, as it may help you some day as well.

The scenario was the following:
I was using a Human Service (HS) with a Coach that consisted of a Document List and a Document Viewer. My BPM version was 8.5.5 but the exposed behavior is the same in 8.5.0.1 and 8.5.6 as well.

Here is my HS and the Document List Configuration:

As you can see, I used a custom Search Service. My goal was to filter the document list based on the Content Type of the documents stored. I wanted to accomplish that my filter looked up the ContentType in a local variable, so I could simply change the value of the variable without touching my search criteria to adapt my searches.

To do so, I added a search criterion in the Search Service by browsing the Content Filters tab and clicking the "Add Search Criterion..." button:

This will add a new criteria. As I wanted to check for the Mime Type, I selected Mime Type in the first field, and selected "is equal to" in the second field:

In the third field as a first test I wrote "application/pdf" (without the quotes) to see, if it would work:

I ran the HS and it did work:

Now I wanted to use a variable instead of hardcoding the MimeType in my Search Criteria. So I created a new Local Input variable named "ContentType" and set it's default value to "application/pdf":

And I adapted my Search Criteria by entering the name of my variable (tw.local.ContentType) into the third field:

I ran the HS and was surprised to see the following results:

Why was that?

Looking at the DataMapping, I found the following CMIS query:

"SELECT cmis:name, cmis:contentStreamMimeType, cmis:objectId, cmis:versionSeriesId, IBM_BPM_Document_FileNameURL, IBM_BPM_Document_FileType FROM IBM_BPM_Document WHERE (cmis:contentStreamMimeType = 'tw.local.ContentType') ORDER BY cmis:name ASC"

As you may note, the variable name I entered in the search criteria was interpreted as a string. No surprise this was not working. There was no document with a Mime Type of "tw.local.ContentType".

So, how was I able to solve it?

It is fairly simple, just follow these three steps:

The result will look like this:

Note the different font, compared to when I wrote the variable name in the field manually:

Looking at the Data Mapping now, I saw the following CMIS query:

"SELECT cmis:name, cmis:contentStreamMimeType, cmis:objectId, cmis:versionSeriesId, IBM_BPM_Document_FileNameURL, IBM_BPM_Document_FileType FROM IBM_BPM_Document WHERE (cmis:contentStreamMimeType = '" + tw.local.ContentType + "') ORDER BY cmis:name ASC"

Now that looked way better. to confirm it was working, I simply re-ran the HS:

And it worked like a charm.

I hope this will help you some day. And if it does not help, take two of these and call me in the morning.

Yours
Doc D

Dear Friends of the Debugging-Fun,

A few days ago, I was presented an interesting issue. One of my customers experienced an unacceptable wait problem while starting their BPM AppCluster.
As always, the first step is to look at the SystemOut.log to see, if there is anything interesting in there.
In this case, there were a vast numer of DB queries, similar to this:

select data,version_id from lsw_bpd where version_id in (select distinct ver.po_version_id from lsw_po_versions ver inner join lsw_snapshot snap on (ver.branch_id=snap.branch_id and ver.start_seq_num<=snap.seq_num and ver.end_seq_num > snap.seq_num) where ver.po_type=25 and snap.name is not null)

Yep, yet again another Performance debugging.

As my customer mentioned the delay starts right then, when cache settings were loaded, I checked the SystemOut.log for anything Cache related during the start-up.

I found the following line:

000000ae wle I CWLLG2155I: Cache settings read have been from file file:

/opt/IBM/BPM/v85/BPM/Lombardi/process-server/lib/procsrv_resources.jar!/LombardiTeamWorksCache.xml.

As you can see, the threadID for that activity is 000000ae. So I grepped for 000000ae to see the whole thread.

And I was quite surprised to see a !9 MINUTE! delay in the start-up. You know, most of the performance cases we see are on a very high level, meaning we are talking of improvements of a few seconds. But this one, I have to tell you, had a good point. Now 9 minutes is an awefully long time to wait. 9 minutes - that is about 2 cups of coffee. Too long, as you will most likely agree.

From the information in the logs it seemed that the delay was related to the Cache, as it occured between the cache settings being loaded and the cache being initialized.

So, where could this be coming from? Maybe some slow DB causing this delay? Well, we do not yet have enough information to tell, hence we need some traces.

The following trace string is the one to start with for such issues:

*=info:WLE.*=all:WAS.clientinfopluslogging=all:com.ibm.ws.rsadapter.jdbc.WSJdbcPreparedStatement=all

The trace.log gives us more info.

We can see the known code from the screenshot above "CWLLG2155I" and some cache activities for e.g. LRU Cache, BDAC(BusinessDataAliasCache), etc.

[3/24/15 9:10:09:109 EET] 000000ae wle           I   CWLLG2155I:  Cache settings read have been from file file:/opt/IBM/BPM/v85/BPM/Lombardi/process-server/lib/procsrv_resources.jar!/LombardiTeamWorksCache.xml
[3/24/15 9:10:09:749 EET] 000000ae wle_versionin 3 com.lombardisoftware.utility.collections.LRUCache createCache maxSize :64
[3/24/15 9:10:09:749 EET] 000000ae wle_versionin 3 com.lombardisoftware.utility.collections.LRUCache <init> New LRUCache created :853f63c0
 

Here we can see the Cache size, which reminds me of a useful article on how to configure them for tuning purposes. Find the link here.

[3/24/15 9:10:17:496 EET] 000000ae wle           1 com.lombardisoftware.core.cache.LocalCache initCache BusinessDataAliasesCache initC()
[3/24/15 9:10:17:496 EET] 000000ae wle           1   BDAC - initialized
[3/24/15 9:10:17:496 EET] 000000ae wle           1   BDAC - loadCacheData(name=BusinessDataAliasesCache, key=*
[3/24/15 9:10:17:500 EET] 000000ae wle           > com.lombardisoftware.client.delegate.common.ServiceLocator lookup ENTRY jdbc/TeamWorksDB

I took a deeper look at the cache activities and stumbled across the following:

The BDAC cache load started at: 09:10:17

And it finished at: 09:16:26

So, what does this mean? These are 6 minutes only for the BDAC cache (which is 2/3 of 9 minutes load time). Aha!

So, now we need some further info on the BDAC. Upon further research, I found this:

http://www-01.ibm.com/support/docview.wss?uid=swg1JR47818

*  Searchable business data aliases are    *

*  the columns that you can use in saved   *

*  searches, the TWSearch API, and the     *

*  REST Search API. If you set the         *

*  <use-business-aliases-for-process-      *

*  instances> property value to "false",   *

*  the list of searchable business data    *

*  aliases are returned based on           *

*  snapshot definitions.                   *

This APAR was introduced for BPM 7.5.1.2 with a new property named <use-business-aliases-for-process-instances>.
The default value for that property is " T R U E ".

TRUE means that the list of searchable Business data aliases are returned only when they are used in actual process instances.

If FALSE is selected, the Business data aliases will be created at the server startup already BEFORE the first access by process instances. If there is  a large number of BPDs, searching all the BPDs can take a very long time.

The more process applications are deployed on server the more aliases will be created, the longer the cache load time takes.

So, if this was introduced in 7.5.1.2 why did I still see this in 8.5.5? APAR JR47818 is part of BPM v8.5.5.

Hm, what could have happened here?

As my grandmother would have said: Never trust a running config (if she had known what a running config was).  Hence lets have a look at the 99local.xml file on my BPM 8.5.5 setup to verify the default configuration for that attribute.

Indeed, the value is set to " F A L S E " !

Checking the customer's 99local.xml and 100Custom.xml showed the same.

Bingo!

Let's wrap up our findings:

1) APAR JR47818 (with BPM 7.5.1.2 ) introduced a new property <use-business-aliases-for-process-instances>. The default value for that property is " T R U E ".

2) BPM 8.5.5.0 includes APAR JR47818 but in that version the default value for the property <use-business-aliases-for-process-instances>  is " F A L S E ".

That is quite a surprise! But at least, we know what to do next. 
Exactly! We need to change that property to true.

So I advised my customer to change the setting for that property to " T R U E " and the problem was solved.

As you can see, sometimes all it takes is a bit of time and research to tackle these kind of issues. 
And if this article does not help, take two of these  and call me in the morning.

Yours,
Doc D.

Good morning my dearest debuggers,

Today, I would like to share a new IBMSupportTV video with you. It shows, how to capture HTTP traffic using Fiddler and can become quite handy if IBM Support asks you for a fiddler trace.

You will find it on the IBMSupportTV youtube channel.

And if this does not help you gathering the trace, take two of these  and call me in the morning.

Yours
Dr. D