Hi Francis,

The most up-to-date instructions for building BlackTie can be interred from the CI script we have checked into the source repo:

narayana/narayana.sh at master · jbosstm/narayana · GitHub

Those are run successfully with every build so it should work fine.

Please also note a facility of Maven is to be able to build without running the tests. You can do this with -DskipTests on the ./build.sh command lines. So for example:

./build.sh -f blacktie/wildfly-blacktie/pom.xml clean install -DskipTests

./build.sh -f blacktie/pom.xml clean install -Dbpa=<e.g. centos55x32>  -DskipTests

In terms of the APR issue hopefuly zhfeng can answer that one.

Thanks,

Tom

Also, once its building fine please do run quickstart/blacktie/xatmi/fooapp at master · jbosstm/quickstart · GitHub to verify that you have a functioning server.

Hi Francis,

In the term of the c++ build errors, I think we had met it with [JBTM-2260] BlackTie does not build on CentOS 7 - JBoss Issue Tracker. So it looks like you needs to rebuild all of the third dependencies by the new bpa with "centos70x32" since you want to create 32bit XATMI servers on a 64bit Centos 7 server. I think we only have the "centos70x64" in the repo.

you can refer to the Building Thirdparty Dependencies and it might be out of date as it builds on the CentOS 5. I will check them on the CentOS 7 and update it.

Hi Francis,

It is not one I have seen before, but our CI box builds WildFly itself rather than using the nexus repo. Perhaps they are not pushing that module out to nexus for some reason yet? They certainly had the previous release as uploaded on April 12th: Index of /groups/public/org/wildfly/wildfly-messaging-activemq

Anyway, you can circumvent the issue by downloading and building wildfly locally:

git clone git@github.com:wildfly/wildfly.git

cd wildfly

./build.sh clean install -DskipTests

Hope that helps,

Tom

Hi Francis,

Do you run the xatmi client and the server on the same machine ? also the wildfly server ?

I noticed that you start the wildfly on the address "172.17.0.5" and start the xatmi server with "./server -i 1 -s fooapp -p 12341 -t 127.0.0.1:8881" that means the default address is "localhost"

can you run the wildfly with the localhost and try the tests again please ?

if it happens again, it could be helpful to send me the blacktie.log and server.log for checking.

Thanks,

Amos

Hi Francis,

This is what we are getting on the latest CI run:

     [exec] Quickstart: Running fooapp

     [exec]

     [exec] BUILD SUCCESSFUL

     [exec] Total time: 3 seconds

     [exec] Checking for host: lancel.eng.hst.ams2.redhat.com or ip: 10.39.168.26

     [exec]  [33m03:23:36,697 WARN  [org.jboss.as.ejb3] (Thread-6 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [0m03:23:36,827 INFO  [org.apache.activemq.artemis.core.server] (ServerService Thread Pool -- 101) AMQ221003: trying to deploy queue jms.queue.BTR_.fooapp1

     [exec]  [0m2016-08-04 03:23:37,222 [0x2afd45a392b0] INFO  (AtmiBrokerServer         :938 ) - advertised service .fooapp1

     [exec]  [33m03:23:37,292 WARN  [org.jboss.as.ejb3] (Thread-1 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [0m03:23:37,400 INFO  [org.apache.activemq.artemis.core.server] (ServerService Thread Pool -- 103) AMQ221003: trying to deploy queue jms.queue.BTR_FOOAPP

     [exec]  [0m [31m03:23:37,651 ERROR [org.jboss.narayana.blacktie.jatmibroker.core.transport.hybrid.SocketReceiverImpl] (Thread-197) receiver Socket[addr=localhost/127.0.0.1,port=12341,localport=51287] run failed with java.io.IOException: Socket Closed

     [exec]  [0m2016-08-04 03:23:37,699 [0x2afd45a392b0] INFO  (AtmiBrokerServer         :938 ) - advertised service FOOAPP

     [exec] 2016-08-04 03:23:37,699 [0x2afd45a392b0] INFO  (AtmiBrokerServer         :243 ) - Server 1 Running

     [exec] 2016-08-04 03:23:37,700 [0x2afd45a392b0] INFO  (AtmiBrokerServer         :645 ) - Server waiting for requests...

     [exec]  [33m03:23:37,975 WARN  [org.jboss.as.ejb3] (Thread-5 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [0m03:23:38,040 INFO  [org.apache.activemq.artemis.core.server] (ServerService Thread Pool -- 101) AMQ221003: trying to deploy queue jms.queue.BTR_.fooapp2

     [exec]  [0m2016-08-04 03:23:38,305 [0x2af88a7972b0] INFO  (AtmiBrokerServer         :938 ) - advertised service .fooapp2

     [exec]  [33m03:23:38,626 WARN  [org.jboss.as.ejb3] (Thread-3 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m2016-08-04 03:23:38,897 [0x2af88a7972b0] INFO  (AtmiBrokerServer         :938 ) - advertised service FOOAPP

     [exec] 2016-08-04 03:23:38,897 [0x2af88a7972b0] INFO  (AtmiBrokerServer         :243 ) - Server 2 Running

     [exec] 2016-08-04 03:23:38,897 [0x2af88a7972b0] INFO  (AtmiBrokerServer         :645 ) - Server waiting for requests...

     [exec]

     [exec] BUILD SUCCESSFUL

     [exec] Total time: 3 seconds

     [exec] 2016-08-04 03:23:42,780 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:43,011 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:43,016 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:43,273 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:43,277 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:43,509 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:43,514 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:43,733 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:43,738 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:43,960 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:43,968 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:44,180 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:44,185 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:44,416 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:44,421 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:44,634 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:44,638 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:44,857 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] 2016-08-04 03:23:44,861 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Calling tpcall with input: THIS IS YOUR CLIENT SPEAKING

     [exec] 2016-08-04 03:23:45,084 [0x2abecbbaf2b0] INFO  (AtmiBrokerLogc           :60  ) - Called tpcall with length: 15 output: BAR SAYS HELLO and status: 0 and tperrno: 0

     [exec] Checking for host: lancel.eng.hst.ams2.redhat.com or ip: 10.39.168.26

     [exec]  [33m03:23:46,480 WARN  [org.jboss.as.ejb3] (Thread-5 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieAdminServiceXATMI message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [33m03:23:46,802 WARN  [org.jboss.as.ejb3] (Thread-6 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [33m03:23:47,094 WARN  [org.jboss.as.ejb3] (Thread-3 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0mServer shutdown successfully: fooapp with id: 1

     [exec] waiting for fooapp:1 shutdown complete

     [exec] fooapp:1 shutdown complete

     [exec]  [33m03:23:50,412 WARN  [org.jboss.as.ejb3] (Thread-7 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieAdminServiceXATMI message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [33m03:23:51,437 WARN  [org.jboss.as.ejb3] (Thread-4 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0m [33m03:23:51,783 WARN  [org.jboss.as.ejb3] (Thread-2 (ActiveMQ-client-global-threads-1010832249)) WFLYEJB0485: Transaction type NEVER is unspecified for the onMessage method of the BlacktieStompAdministrationService message-driven bean. It will be handled as NOT_SUPPORTED.

     [exec]  [0mServer shutdown successfully: fooapp with id: 2

     [exec] waiting for fooapp:2 shutdown complete

     [exec] fooapp:2 shutdown complete

That box is not particularly overpowered from what I know of it. It is a virtual machine running on old hardware.

I agree with Amos' recommendation. If not done so already, please enable some additional trace logging in the WildFly server:

It looks strange. I had checked our CI server.log and it was missing the artemis-native-64 also. So it might not be the issue. Can you send us all of the blacktie.log and server.log ? I could look into what causes the 3 seconds delay after the third tpcall.

Thanks

I checked the source for Artemis in WildFly 10. It tries to load the library from a list and the 64 bit one is first:

https://github.com/rh-messaging/jboss-activemq-artemis/blob/1.1.0.wildfly-011/artemis-native/src/main/java/org/apache/activemq/artemis/jlibaio/LibaioContext.java#L85

It should be fine so long as you are not getting the warning for artemis-native-32 as well (or this message: https://github.com/rh-messaging/jboss-activemq-artemis/blob/1.1.0.wildfly-011/artemis-native/src/main/java/org/apache/activemq/artemis/jlibaio/LibaioContext.java#L104)

However NIO or AIO, neither should have a 3 second pause in them. Our CI nodes are not overpowered at all and as I mentioned are on aging hardware.

As Amos says we need the blacktie.log and blacktie-J.log from the fooapp folder and the server.log from the wildfly/standalone/logs folder (with at least trace in the components I mentioned earlier).

What happens if you run the app for a single interction but scripted in a tight loop for say 100 iterations, do any of those exhibit a delay? Anyway, the logs should help clear up where the delay is coming from.

The cause of the hang is due to a session map lock:

https://github.com/jbosstm/narayana/blob/master/blacktie/hybrid/src/main/cpp/HybridConnectionImpl.cxx#L316

The map is locked while we delete the session so other threads can't create sessions. We could look at doing the "delete session;" after the "sessionMapLock->unlock();" However I think in this circumstance I am not sure it can help as the thread that is waiting is used again later and so all that will actually happen is you are likely to get a delay slightly later. That said Francis perhaps you can you try a patch for that please to see if it addresses your problem?

So as to where the delay is coming from I see these log lines for thread 0xf42ffb40 (which has the lock on the map I was mentioning):

2016-08-05 13:08:55,426 [0xf42ffb40] TRACE (HybridSocketSessionImpl  :221 ) - delete codec (https://github.com/jbosstm/narayana/blob/master/blacktie/hybrid/src/main/cpp/HybridSocketSessionImpl.cxx#L221)

2016-08-05 13:08:55,426 [0xf42ffb40] DEBUG (HybridSocketEndpointQueue:201 ) - disconnect (narayana/HybridSocketEndpointQueue.cxx at master · jbosstm/narayana · GitHub)

2016-08-05 13:08:58,424 [0xf42ffb40] DEBUG (HybridSocketEndpointQueue:97  ) - destroy called: 0xf3900638 (narayana/HybridSocketSessionImpl.cxx at master · jbosstm/narayana · GitHub

The line I can attribute the delay to is:

narayana/HybridSocketSessionImpl.cxx at master · jbosstm/narayana · GitHub

Unfortunately we don't log the queue's thread name in the Session CTOR but based on the timings I expect this is the background thread we are waiting for:

2016-08-05 13:08:58,423 [0xf1affb40] DEBUG (HybridSocketEndpointQueue:448 ) - from HybridSocketEndpointQueue closing socket

It previously reported:

2016-08-05 13:08:55,600 [0xf1affb40] DEBUG (HybridSocketEndpointQueue:437 ) - add socket in pollset

Which leads me to conclude it is blocked here:

https://github.com/jbosstm/narayana/blob/master/blacktie/hybrid/src/main/cpp/HybridSocketEndpointQueue.cxx#L392

Now, DEF_POLL_TIMEOUT is defined here (no prizes for guessing three seconds):

narayana/HttpServer.h at master · jbosstm/narayana · GitHub

All this leads me to conclude that the poll is timing out rather than getting woken during a shutdown. Hopefully Amos can identify the cause from there. I am not seeing calls to apr_pollset_wakeup in our code (bottom of Apache Portable Runtime: Poll Routines) but maybe the apr_pollset_remove can do that somehow on some platforms.

Just to mention that zhfeng is still looking at this. We don't see it happen on CI and I don't see it on my box (Windows) but we don't build 32bit Centos7. Amos, can you try that too please?