Friday, September 30, 2011

lsof to find which process is keeping a socket open

I know I must already have blogged this...

If the port is 10011, do this:

/usr/sbin/lsof -nl | egrep "TCP|UDP" | grep 10011


COMMAND     PID     USER   FD   TYPE             DEVICE   SIZE/OFF    NODE NAME

java      10747      574   13u  IPv4 0xe0000004a31e6680        0t0     TCP 127.0.0.1:55785->127.0.0.1:10011 (ESTABLISHED)
java      10747      574   15u  IPv4 0xe0000004ab25aa00   0t296774     TCP 10.3.255.175:53916->10.3.255.175:10011 (ESTABLISHED)
java      10748      574   13u  IPv4 0xe0000004638b6d00     0t9957     TCP 10.3.255.175:53927->10.3.255.175:10011 (ESTABLISHED)
java      10748      574   15u  IPv4 0xe000000462b22100        0t0     TCP 127.0.0.1:55786->127.0.0.1:10011 (ESTABLISHED)
java      10749      574   13u  IPv4 0xe000000460469100        0t0     TCP 127.0.0.1:55787->127.0.0.1:10011 (ESTABLISHED)
java      10749      574   15u  IPv4 0xe0000004c2dce380   0t298907     TCP 10.3.255.175:53921->10.3.255.175:10011 (ESTABLISHED)
java      10750      574   13u  IPv4 0xe000000460f47680   0t300255     TCP 10.3.255.175:53935->10.3.255.175:10011 (ESTABLISHED)
java      10750      574   15u  IPv4 0xe000000462b22400    0t34979     TCP 127.0.0.1:54761->127.0.0.1:10011 (ESTABLISHED)
java      21200      574  597u  IPv4 0xe000000497104380     0t1688     TCP 10.3.255.168:55375->10.3.255.168:10011 (ESTABLISHED)
java      27806      574  342u  IPv4 0xe000000483b10400     0t2961     TCP 10.3.255.168:10011->10.3.255.168:55375 (ESTABLISHED)
java      27806      574  346u  IPv4 0xe00000049fe42a00     0t2956     TCP 127.0.0.1:10011->127.0.0.1:54761 (ESTABLISHED)
java      27806      574  351u  IPv4 0xe000000482c52980      0t220     TCP 127.0.0.1:10011->127.0.0.1:55785 (ESTABLISHED)
java      27806      574  356u  IPv4 0xe000000449aebc80        0t0     TCP 10.3.67.168:10011 (LISTEN)
java      27806      574  363u  IPv4 0xe000000462cfc100        0t0     TCP 10.3.255.175:10011 (LISTEN)
java      27806      574  364u  IPv4 0xe0000004ac2f7c80        0t0     TCP 10.3.255.168:10011 (LISTEN)
java      27806      574  365u  IPv4 0xe0000004ad028400        0t0     TCP 127.0.0.1:10011 (LISTEN)
java      27806      574  366u  IPv4 0xe0000004bf415980        0t0     TCP 10.3.255.174:10011 (LISTEN)
java      27806      574  367u  IPv4 0xe0000004d24b3400      0t220     TCP 127.0.0.1:10011->127.0.0.1:55786 (ESTABLISHED)
java      27806      574  368u  IPv4 0xe0000004bf415680        0t0     TCP 10.3.255.179:10011 (LISTEN)
java      27806      574  369u  IPv4 0xe00000049e0a3680      0t220     TCP 127.0.0.1:10011->127.0.0.1:55787 (ESTABLISHED)
java      27806      574  378u  IPv4 0xe0000004638b6700   0t244556     TCP 10.3.255.175:10011->10.3.255.175:53916 (ESTABLISHED)
java      27806      574  379u  IPv4 0xe0000001ef703980   0t247992     TCP 10.3.255.175:10011->10.3.255.175:53921 (ESTABLISHED)
java      27806      574  382u  IPv4 0xe0000004bbae2c80    0t10277     TCP 10.3.255.175:10011->10.3.255.175:53927 (ESTABLISHED)
java      27806      574  397u  IPv4 0xe00000046080da00   0t246284     TCP 10.3.255.175:10011->10.3.255.175:53935 (ESTABLISHED)
java      27806      574  397u  IPv4 0xe00000046080da00   0t246284     TCP 10.3.255.175:10011->10.3.255.175:53935 (ESTABLISHED)





you can see that the same socket is reported twice, once on the receiving side and the other on the sending side

Here you can find a splendid tutorial on lsof.

Thursday, September 29, 2011

BEA-171520 Could not obtain an exclusive lock for directory


Warning EmbeddedLDAP BEA-171520 Could not obtain an exclusive lock for directory: /home/osbadmin/pierretests/domains/osb_domain/servers/ms1/data/ldap/ldapfiles. Waiting for 10 seconds and then retrying in case existing WebLogic Server is still shutting down.



Just delete any .lok file in that directory and try again

If you find this:


Unable to obtain lock on /home/osbadmin/pierretests/domains/osb_domain/servers/ms1/tmp/ms1.lok. Server may already be running


then
a) make sure server is not running
b) rm /home/osbadmin/pierretests/domains/osb_domain/servers/ms1/tmp/ms1.lok

WLST deleting Durable Subscribers

I was following Kathiravan excellent document http://jeanfrancoisoracle.free.fr/Tools/JMS_Message_Management.doc

to delete durable subscribers in WLST,
slightly modified here to delete ALL durable subscribers:

# connect to the server
connect(‘weblogic’,’weblogic’,’t3://localhost:7001’)

# navigate to the root of the server’s Runtime MBean tree
serverRuntime()

# navigate to the JMSRuntime
cd(‘JMSRuntime/myserver.jms’)

# navigate to the JMSServer that the queue is on
cd(‘JMSServers/MyJMSServer1’)

# navigate to “MyTopic1” where the durable subscriber will be created
cd (‘Destinations/MyJmsSystemResource!MyTopic1’)

# get all the durable subscriber runtime MBeans on this topic
# note that this operation would return an array of dsub runtimes
dsubs1=cmo.getDurableSubscribers()

# then pass it as an argument to the delete method as below
for ds in dsubs1:
    try:
        cmo.destroyJMSDurableSubscriberRuntime(ds)
    except:
        print "Unexpected error:", sys.exc_info()[0]
 




If the Durable Subscriber is active, you get this error:


weblogic.jms.common.JMSException: Active topicSubscriber is using this subscription right now
at weblogic.jms.backend.BEConsumerImpl.delete(BEConsumerImpl.java:968)
at weblogic.jms.backend.BEDurableSubscriberRuntimeMBeanImpl.destroy(BEDurableSubscriberRuntimeMBeanImpl.java:121)
at weblogic.jms.backend.BEDestinationRuntimeMBeanImpl.destroyJMSDurableSubscriberRuntime(BEDestinationRuntimeMBeanImpl.java:85)



so make sure you kill the Durable Subscriber process before deleting its subscription.... I wish there was a better way...

WLST to create a SAF Agent with an Imported Destination (Queue)

edit()
startEdit()

#SAF Agent
cd('/')
cmo.createSAFAgent('SAFAgent-0')

cd('/SAFAgents/SAFAgent-0')
set('Targets',jarray.array([ObjectName('com.bea:Name=AdminServer,Type=Server')], ObjectName))
cmo.setServiceType('Sending-only')

#JMS Module
cd('/')
cmo.createJMSSystemResource('SystemModule-0')

cd('/SystemResources/SystemModule-0')
set('Targets',jarray.array([ObjectName('com.bea:Name=AdminServer,Type=Server')], ObjectName))

#Remote SAF Context
cd('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0')
cmo.createSAFRemoteContext('RemoteSAFContext-0')

cd('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0/SAFRemoteContexts/RemoteSAFContext-0/SAFLoginContext/RemoteSAFContext-0')
cmo.setLoginURL('t3://yourtargethost:7011')
cmo.setUsername('weblogic')
cmo.setPassword('weblogic')

#Subdeployment
cd('/SystemResources/SystemModule-0')
cmo.createSubDeployment('sd')

cd('/SystemResources/SystemModule-0/SubDeployments/sd')
set('Targets',jarray.array([ObjectName('com.bea:Name=AdminServer,Type=Server')], ObjectName))

cd('/SystemResources/SystemModule-0')
set('Targets',jarray.array([ObjectName('com.bea:Name=AdminServer,Type=Server')], ObjectName))

#SAF imported destinations
cd('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0')
cmo.createSAFImportedDestinations('SAFImportedDestinations-0')

cd('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0/SAFImportedDestinations/SAFImportedDestinations-0')
cmo.setJNDIPrefix('SAFImportedDestinations')
cmo.setSAFRemoteContext(getMBean('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0/SAFRemoteContexts/RemoteSAFContext-0'))
cmo.setSAFErrorHandling(None)
cmo.setTimeToLiveDefault(0)
cmo.setUseSAFTimeToLiveDefault(false)
cmo.setDefaultTargetingEnabled(true)

#SAF Queue
cmo.createSAFQueue('SAFQueue-0')


cd('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0/SAFImportedDestinations/SAFImportedDestinations-0/SAFQueues/SAFQueue-0')
cmo.setRemoteJNDIName('your.remote.queue')

cmo.setNonPersistentQos('At-Least-Once')
cmo.setTimeToLiveDefault(0)
cmo.setUseSAFTimeToLiveDefault(false)
cmo.setLocalJNDIName('your.remote.queue.locally')
cmo.setUnitOfOrderRouting('Hash')

cd('/JMSSystemResources/SystemModule-0/JMSResource/SystemModule-0/SAFImportedDestinations/SAFImportedDestinations-0/MessageLoggingParams/SAFImportedDestinations-0')
cmo.setMessageLoggingEnabled(false)
cmo.setMessageLoggingEnabled(true)
cmo.setMessageLoggingFormat('%header%,JMSCorrelationID,JMSDeliveryMode,JMSDestination,JMSExpiration,JMSMessageID,JMSPriority,JMSRedelivered,JMSReplyTo,JMSTimestamp,JMSType,%properties%')


cd('/')


activate()



Tuesday, September 27, 2011

Monitoring OSB when monitoring is not enabled

Monitoring is a very cool feature of OSB, you can tell any time what is going on in the bus.

If you have no monitoring, there is still something you can do - apart thread dumps.

Go to Server/Monitoring/Threads, and in the Customize Columns enable also
Module, Application and Work Manager

Next to the thread you will see also something like ProxyService_MYPROXYBLA_Proxy270984
which tells you which proxies are pumping right now.

Better than nothing...

WebLogic patch conflicts

Today I was trying to apply some patches to WLS 10.3,
and the bsu told me:

2RCP Failed Validation:

At least one conflict condition has been detected. You must resolve all conflicts before the selected patch can be applied.


Selected patch cannot coexist with the existing patch(es) shown and already applied. Remove the existing patch(es) and try again.

X5NU





Googling around I find this explanation. In reality there is no clue on why they conflict, and which patch should supercede the other...


Well, first of all I have learned that you better shut down all your servers, otherwise you get a nasty error message while removing the patch, something like "unable to create the backup of the patch you were removing".

Disabling a NIC, AKA "cutting the branch on which you are sitting"

Today, in order to reproduce a network related issue, I have disabled the Network Interface of a machine to which I was connected with Remote Desktop.... guess what happened....

The moment I clicked, I knew I had done something stupid... I wish there was a popup reminding you that this is a VERY dangerous operation...



Hugga Wagga

If you have a nasty colleague (I had a couple of them in a distant past - luckily gone) remember they will end up like Hugga Wagga. Smile, ignore them, life is good.



WLST move JMS messages

Thanks to our friends of MiddleWare Magic:

http://middlewaremagic.com/weblogic/?p=6765

that I will never praise enough...



connect('weblogic', 'welcome1', 't3://pierrepc:7011')
easeSyntax()
serverRuntime()
cd('/JMSRuntime/ms1.jms/JMSServers/jmsserver1/Destinations/MS1SystemModule!Q2')
q2 = cmo
cd('/JMSRuntime/ms1.jms/JMSServers/jmsserver1/Destinations/MS1SystemModule!Q1')
q1 = cmo
#THIS WILL MOVE MESSAGES
q1.moveMessages('', q2.getDestinationInfo())

To move messages in small chunks, rather than all in a go:

from weblogic.jms.extensions import JMSMessageInfo
connect('weblogic', 'weblogic1', 't3://acme.com:10001')  
easeSyntax()
serverRuntime()

chunkSize = 25

cd /JMSRuntime/osbpl1ms1.jms/JMSServers/CommonJmsServer1/Destinations/GM_StockDownloadJMSModule!CommonJmsServer1@StockDownloadReprocessQ
sourceQueue = cmo
cd /JMSRuntime/osbpl1ms1.jms/JMSServers/CommonJmsServer1/Destinations/GM_StockDownloadJMSModule!CommonJmsServer1@StockDownloadQ
destinationQueue = cmo

sourceCursor = sourceQueue.getMessages('', 0)
sourceCursorSize = sourceQueue.getCursorSize(sourceCursor)
print "there are", sourceCursorSize, "in source"

sourceMessages = sourceQueue.getNext(sourceCursor, chunkSize )

if sourceMessages != None:
    for message in sourceMessages:
        msgwithbody = JMSMessageInfo(message)
        messageId = msgwithbody.getMessage().getJMSMessageID()
        print 'Message ID           - ' + messageId
        sourceQueue.moveMessages("JMSMessageID='" + messageId + "'", destinationQueue.getDestinationInfo())



Additional useful code:

#move messages to destination
sourceQueue.moveMessages('', destinationQueue.getDestinationInfo())

#send them back to origin
destinationQueue.moveMessages('', sourceQueue.getDestinationInfo())

Move a message based on a Selector messageId = "some id":

sourceQueue.moveMessages("JMSMessageID='ID:<64972.1369647706567.0>'", destinationQueue.getDestinationInfo()) Funnily, if I run:

destinationQueue.importMessages(sourceMessages, True) I get an error message:

importMessages operation not supported with replaceOnly=true

See also http://weblogicserver.blogspot.com/2010/07/using-wlst-script-to-list-messages-from.html?_sm_au_=iVVmZBV2WBRm0Dfr for excellent coding examples.

Monday, September 26, 2011

How to remove those stuck messages in a Distributed Topic

If you have messages current in a Distributed Topic, and you can't persuade the consumers to consume them... and you can't delete them with WLST because there is a bug in the MBean... and you are too lazy to write a Java class...

you can




shutdown all MS

cd $DOMAIN_HOME/servers/yourServer/data/store/default
rm _WLS_YOURSERVER000000.DAT

do the same for all MS

restart

the MS should recreate an empty store.

This if your JMSServer was pointing to the default store.
If it uses a custome FileStore, delete it.

WLST delete messages from a Queue/Topic

connect('weblogic', 'weblogic', 't3:localhost:7001')
serverRuntime()

cd('/JMSRuntime/ManagedServer1.jms/JMSServers/JMS_SRVR_Man01/Destinations/MyJMSModule!JMS_SRVR_Man01@MyDistributedTopic')

cmo.deleteMessages('')


java.lang.UnsupportedOperationException: java.lang.UnsupportedOperationException: deleteMessages(String) not valid for class weblogic.jms.backend.BEDestinationRuntimeMBeanImpl



WTF???

In fact, BEDestinationRuntimeMBeanImpl extends BEMessageManagementRuntimeDelegate, and it's BEMessageManagementRuntimeDelegate who implements
public Integer deleteMessages(String selector)

BEDestinationRuntimeMBeanImpl implements JMSDestinationRuntimeMBean, which doesn't expose the deleteMessages method.

It could very well be that WLST evaluates the Interface, not the Implementation of the cmo...

In fact, when you deleteMessages from WebLogic console, it's directly the weblogic.jms.backend.BEMessageManagementRuntimeDelegate.deleteMessages() which is invoked, and not the BEDestinationRuntimeMBeanImpl.


The same API works for a Queue, but NOT for a Distributed Topic.

PS I have tested on 10.3.4 and the same problem is present.
Workaround: delete all durable subscribers and the messages should disappear :o(((

Sunday, September 25, 2011

Strace

http://linux.die.net/man/1/strace

it's very interesting to use strace to trace all system calls in a process.
If you have strange error messages such as "permission denied" without further details, strace will allow you to get more info on what exactly was being executed at the time the error occurred.

In this example, here is what is run when zipping a file

orauser@ubuntu:/tmp$ echo ciao > ciao.txt
orauser@ubuntu:/tmp$ strace zip ciao.zip ciao.txt




execve("/usr/bin/zip", ["zip", "ciao.zip", "ciao.txt"], [/* 41 vars */]) = 0
brk(0) = 0x8f37000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb777a000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=55536, ...}) = 0
mmap2(NULL, 55536, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb776c000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/libbz2.so.1.0", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\0\20\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=70036, ...}) = 0
mmap2(NULL, 68840, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xc6c000
mmap2(0xc7b000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xf) = 0xc7b000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220o\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1434180, ...}) = 0
mmap2(NULL, 1444360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x5f5000
mprotect(0x74f000, 4096, PROT_NONE) = 0
mmap2(0x750000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15a) = 0x750000
mmap2(0x753000, 10760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x753000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb776b000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb776a000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb776bb40, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0x750000, 8192, PROT_READ) = 0
mprotect(0xc7b000, 4096, PROT_READ) = 0
mprotect(0x8073000, 4096, PROT_READ) = 0
mprotect(0x949000, 4096, PROT_READ) = 0
munmap(0xb776c000, 55536) = 0
brk(0) = 0x8f37000
brk(0x8f58000) = 0x8f58000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=8322432, ...}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb756a000
mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x2a1) = 0xb7779000
close(3) = 0
open("/etc/localtime", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7778000
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 4096) = 2819
_llseek(3, -24, [2795], SEEK_CUR) = 0
read(3, "\nPST8PDT,M3.2.0,M11.1.0\n", 4096) = 24
close(3) = 0
munmap(0xb7778000, 4096) = 0
rt_sigaction(SIGINT, {0x804ab90, [INT], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGTERM, {0x804ab90, [TERM], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGABRT, {0x804ab90, [ABRT], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGBUS, {0x804ab90, [BUS], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGILL, {0x804ab90, [ILL], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGSEGV, {0x804ab90, [SEGV], SA_RESTART}, {SIG_DFL, [], 0}, 8) = 0
open("ciao.zip", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
stat64("ciao.txt", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
time(NULL) = 1316294578
stat64("ciao.zip", 0x8076c40) = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/i386-linux-gnu/gconv/gconv-modules", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=55868, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7778000
read(3, "# GNU libc iconv configuration.\n"..., 4096) = 4096
read(3, "B1.002//\nalias\tJS//\t\t\tJUS_I.B1.0"..., 4096) = 4096
read(3, "59-3\t1\nmodule\tINTERNAL\t\tISO-8859"..., 4096) = 4096
read(3, "859-14//\nalias\tISO-IR-199//\t\tISO"..., 4096) = 4096
read(3, "CDIC-DK-NO-A//\tEBCDIC-DK-NO-A\t1\n"..., 4096) = 4096
read(3, "\t\tIBM281//\t\tIBM281\t\t1\n\n#\tfrom\t\t\t"..., 4096) = 4096
read(3, "\tIBM863\t\t1\n\n#\tfrom\t\t\tto\t\t\tmodule"..., 4096) = 4096
read(3, "\tmodule\t\tcost\nalias\tIBM-939//\t\tI"..., 4096) = 4096
read(3, "\t\t\tmodule\t\tcost\nalias\tEUCCN//\t\t\t"..., 4096) = 4096
read(3, "C_P27-1//\t\tINTERNAL\t\tIEC_P27-1\t1"..., 4096) = 4096
read(3, "\t\t\tmodule\t\tcost\nalias\tMACIS//\t\t\t"..., 4096) = 4096
read(3, "X0213\t1\nmodule\tINTERNAL\t\tShift_J"..., 4096) = 4096
read(3, "40//\t\tIBM1140//\nalias\tCP1140//\t\t"..., 4096) = 4096
read(3, "\nmodule\tINTERNAL\t\tIBM16804//\t\tIB"..., 4096) = 2620
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7778000, 4096) = 0
time(NULL) = 1316294578
stat64("ciao.txt", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
open("ciao.zip", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
close(3) = 0
stat64("ciao.zip", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
unlink("ciao.zip") = 0
gettimeofday({1316294578, 909680}, NULL) = 0
getpid() = 6145
open("zijnRHbC", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 3
fcntl64(3, F_GETFL) = 0x8002 (flags O_RDWR|O_LARGEFILE)
fstat64(3, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7778000
_llseek(3, 0, [0], SEEK_CUR) = 0
munmap(0xb7778000, 4096) = 0
_llseek(3, 0, [0], SEEK_CUR) = 0
_llseek(3, 0, [0], SEEK_SET) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7778000
write(1, " adding: ciao.txt", 18 adding: ciao.txt) = 18
stat64("ciao.txt", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2819, ...}) = 0
stat64("ciao.txt", {st_mode=S_IFREG|0644, st_size=5, ...}) = 0
open("ciao.txt", O_RDONLY|O_LARGEFILE) = 4
write(3, "PK\3\4\24\0\10\0\10\0\321r1?\0\0\0\0\0\0\0\0\5\0\0\0\10\0\34\0ci"..., 66) = 66
read(4, "ciao\n", 65536) = 5
read(4, "", 65531) = 0
_llseek(3, 65, [65], SEEK_SET) = 0
_llseek(3, 66, [66], SEEK_SET) = 0
close(4) = 0
write(3, "ciao\n", 5) = 5
_llseek(3, 0, [0], SEEK_SET) = 0
write(3, "PK\3\4\n\0\0\0\0\0\321r1?h};\25\5\0\0\0\5\0\0\0\10\0\34\0ci"..., 66) = 66
_llseek(3, 71, [71], SEEK_SET) = 0
write(1, " (stored 0%)\n", 13 (stored 0%)
) = 13
write(3, "PK\1\2\36\3\n\0\0\0\0\0\321r1?h};\25\5\0\0\0\5\0\0\0\10\0\30\0"..., 100) = 100
close(3) = 0
lstat64("ciao.zip", 0xbf961600) = -1 ENOENT (No such file or directory)
rename("zijnRHbC", "ciao.zip") = 0
chmod("ciao.zip", 0100644) = 0
exit_group(0) = ?

If you want to know all the "open" commands, the do

strace -e open youcommand



Friday, September 23, 2011

Jurassic Park, Velociraptors and Social Intelligence

Tonight I was very sick so I could not engage my brain in anything more challenging than watching the Trilogy Of Jurassic Park.

It's fascinating - although with little scientific foundation - the Theory of Social Hunting Behavior of Raptors - raptors would be highly successful because they would go hunting in coordinated packs.

See:

http://en.wikipedia.org/wiki/Velociraptor

and the power of Social Intelligence to achieve coordinated results.

According to paleontologists, velociraptors were not all that smart and big as depicted in the movie.



The underlying truth is this: to succeed individually,
you must be able to connect to other beings and pursuit a common goal, fusing energies together.

So, when you have a problem, get your out of your chair an go talk to other people who might have a clue.... be a Velociraptor (sounds like a Bicycle Thief) !

weblogic.jms.frontend.FEConnectionFactoryImpl

If you get a STUCK thread on the JMS FrontEnd:

<Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '15' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "655" seconds working on the request "weblogic.jms.frontend.FEConnectionFactoryImpl", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace:
weblogic.rmi.extensions.DisconnectMonitorListImpl.addDisconnectListener(DisconnectMonitorListImpl.java:78)
weblogic.messaging.dispatcher.DispatcherWrapperState.addPeerGoneListener(DispatcherWrapperState.java:414)
weblogic.messaging.dispatcher.DispatcherWrapperState.<init>(DispatcherWrapperState.java:79)
weblogic.messaging.dispatcher.DispatcherManager.addDispatcherReference(DispatcherManager.java:115)
weblogic.jms.dispatcher.JMSDispatcherManager.addDispatcherReference(JMSDispatcherManager.java:191)
weblogic.jms.frontend.FEConnectionFactory.connectionCreateInternal(FEConnectionFactory.java:360)
weblogic.jms.frontend.FEConnectionFactoryImpl.connectionCreateInternal(FEConnectionFactoryImpl.java:79)
weblogic.jms.frontend.FEConnectionFactoryImpl.connectionCreateRequest(FEConnectionFactoryImpl.java:62)
weblogic.jms.frontend.FEConnectionFactoryImpl_WLSkel.invoke(Unknown Source)
weblogic.rmi.internal.BasicServerRef.invoke(BasicServerRef.java:589)
weblogic.rmi.cluster.ClusterableServerRef.invoke(ClusterableServerRef.java:230)
weblogic.rmi.internal.BasicServerRef$1.run(BasicServerRef.java:477)
weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
weblogic.security.service.SecurityManager.runAs(Unknown Source)
weblogic.rmi.internal.BasicServerRef.handleRequest(BasicServerRef.java:473)
weblogic.rmi.internal.wls.WLSExecuteRequest.run(WLSExecuteRequest.java:118)
weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
weblogic.work.ExecuteThread.run(ExecuteThread.java:173)


check for instance that the firewall on the client is not blocking communication from the Server, see also here:

https://forums.oracle.com/forums/thread.jspa?threadID=837177

weblogic.socket.MaxMessageSizeExceededException

I am getting this:

<Error> <Socket> <BEA-000403> <IOException occurred on socket: Socket[addr=10.10.200.200/10.10.200.200,port=4243,localport=7011]

weblogic.socket.MaxMessageSizeExceededException: Incoming message of size: '10000080' bytes exceeds the configured maximum of: '10000000' bytes for protocol

: 't3'.

weblogic.socket.MaxMessageSizeExceededException: Incoming message of size: '10000080' bytes exceeds the configured maximum of: '10000000' bytes for protocol:

't3'

at weblogic.socket.AbstractMuxableSocket.incrementBufferOffset(AbstractMuxableSocket.java:262)

at weblogic.rjvm.t3.MuxableSocketT3.incrementBufferOffset(MuxableSocketT3.java:343)

at weblogic.socket.SocketMuxer.readReadySocketOnce(SocketMuxer.java:910)

at weblogic.socket.SocketMuxer.readReadySocket(SocketMuxer.java:859)

at weblogic.socket.DevPollSocketMuxer.processSockets(DevPollSocketMuxer.java:120)

at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)

at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)

at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)

at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)

>

You can identify the client issuing the request looking at the IP address (10.10.200.200).


Solution:

On the receiving side, go to:
Server/Protocols/General/Maximum Message Size

and increase it.

"The maximum number of bytes allowed in messages that are received over all supported protocols, unless overridden by a protocol-specific setting or a custom channel setting."


The console help on this attribute is very interesting:



The order of precedence for setting message size maximums is as follows:

- A channel-wide maximum in a custom network channel.

- A protocol-specific setting in the default network channel.

See

MaxCOMMessageSize

MaxHTTPMessageSize

MaxIIOPessageSize

MaxT3MessageSize


The message maximum in this attribute.

This maximum message size helps guard against a denial of service attack in which a caller attempts to force the server to allocate more memory than is available thereby keeping the server from responding quickly to other requests.

MBean Attribute:
ServerMBean.MaxMessageSize

Minimum value: 4096

Maximum value: 2000000000

Secure value: 10000000


Related Tasks

Configure T3 protocol
Configure HTTP protocol
Enable and configure IIOP
Enable jCOM
Related Topics

Configuring Network Resources






Otherwise, change the JAVA_OPTIONS to incorporate

-Dweblogic.MaxMessageSize=20000000

Priceless pocket guide to HP-UX

http://users.cis.fiu.edu/~tho01/psg/hpux.html

for instance we learn that to list all NICs, instead of ifconfig you should use:

/etc/lanscan -v

I find this command very confusing.... Linux was far simpler to use...

Thursday, September 22, 2011

Load test for Durable Subscribers

Here is the Java program to create dynamically multiple Durable Subscribers

package durablesubscribers;

import java.util.Hashtable;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import javax.jms.Message;

import javax.jms.TopicConnectionFactory;
import javax.jms.Session;
import javax.jms.Topic;
import javax.jms.TopicConnection;
import javax.jms.TopicSession;
import javax.jms.TopicSubscriber;
import javax.naming.Context;
import javax.naming.InitialContext;

/**
 *
 * @author Pierre
 */
public class DurableSubscriberFactory implements Runnable {
    public static final int NUMBER_OF_THREADS = 50;
    public static final int WAIT_BETWEEN_RECEIVE = 10000;
    
    private String clientId = null;

    public static void main(String[] args) throws Exception {
         ExecutorService service = Executors.newFixedThreadPool(NUMBER_OF_THREADS);
         for (int i = 0; i < NUMBER_OF_THREADS; i++) {
             DurableSubscriberFactory runnable = new DurableSubscriberFactory();
             runnable.setClientId("PV_CLIENTID_" + i);
             service.submit(runnable);
             Thread.sleep(200);
             
         }
    }

    public void run() {
        TopicConnection topicConnection = null;
        try {
            System.out.println("starting");
            // get the initial context, refer to your app server docs for this
            Hashtable<String, String> ht = new Hashtable<String, String>();
            ht.put(Context.INITIAL_CONTEXT_FACTORY, "weblogic.jndi.WLInitialContextFactory");
            ht.put(Context.PROVIDER_URL, "t3://myserver:7011");
            Context ctx = new InitialContext(ht);

            System.out.println("looking up");
            // get the connection factory, and open a connection
            TopicConnectionFactory qcf = (TopicConnectionFactory) ctx.lookup("myConnectionFactory");
            System.out.println("createTopicConnection");
            topicConnection = qcf.createTopicConnection();
            // must specify, otherwise you get an IllegalStateException
            topicConnection.setClientID(getClientId());
            // start connection to receive messages
            topicConnection.start();

            // create topic session off the connection
            System.out.println("createTopicSession");
            TopicSession topicSession = topicConnection.createTopicSession(false, Session.AUTO_ACKNOWLEDGE);

            // get handle on topic, create a durable subscriber and consume messages
            System.out.println("lookup topic");

            // you can only create a Durable Subscriber to a individual member, not to a Distributed Destination
            Topic topic = (Topic) ctx.lookup("JMS_SERVER_01@TOPICNAME");
            System.out.println("create durable subscriber");
            TopicSubscriber topicSubscriber = topicSession.createDurableSubscriber(topic, "PVTEST");
            while (true) {
                System.out.println("receiving....");
                Message message = topicSubscriber.receive();
                System.out.println("received message " + message);
                Thread.sleep(WAIT_BETWEEN_RECEIVE);
            }

        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            // close the queue connection
            if (topicConnection != null) {
                try {
                    topicConnection.close();
                } catch (Exception e) {
                    e.printStackTrace();
                }

            }
        }
    }

    /**
     * @return the clientId
     */
    public String getClientId() {
        return clientId;
    }

    /**
     * @param clientId the clientId to set
     */
    public void setClientId(String clientId) {
        this.clientId = clientId;
    }
}






It works really great.... but when you exit the application, the Durable Subscribers will still appear in the Consumers for the Topic.
If you want to remove them, do this:

package durablesubscribers;

import java.util.Hashtable;

import javax.jms.TopicConnectionFactory;
import javax.jms.Session;
import javax.jms.TopicConnection;
import javax.jms.TopicSession;
import javax.naming.Context;
import javax.naming.InitialContext;

/**
 *
 * @author vernetto
 */
public class UnsubscribeAll {
    public static final int NUMBER_OF_THREADS = 50;

    private String clientId = null;

    public static void main(String[] args) throws Exception {
         for (int i = 0; i < NUMBER_OF_THREADS; i++) {
             UnsubscribeAll runnable = new UnsubscribeAll();
             runnable.setClientId("PV_CLIENTID_" + i);
             runnable.unsubscribe();
             Thread.sleep(200);
         }
    }

    /**
     * @param args the command line arguments
     */
    public void unsubscribe() {
        TopicConnection topicConnection = null;
        try {
            System.out.println("starting");
            // get the initial context, refer to your app server docs for this
            Hashtable<String, String> ht = new Hashtable<String, String>();
            ht.put(Context.INITIAL_CONTEXT_FACTORY, "weblogic.jndi.WLInitialContextFactory");
            ht.put(Context.PROVIDER_URL, "t3://myserver:7011");
            Context ctx = new InitialContext(ht);

            System.out.println("looking up");
            // get the connection factory, and open a connection
            TopicConnectionFactory qcf = (TopicConnectionFactory) ctx.lookup("myConnectionFactory");
            System.out.println("createTopicConnection");
            topicConnection = qcf.createTopicConnection();
            // must specify, otherwise you get an IllegalStateException
            topicConnection.setClientID(getClientId());

            // create topic session off the connection
            System.out.println("createTopicSession");
            TopicSession topicSession = topicConnection.createTopicSession(false, Session.AUTO_ACKNOWLEDGE);

            topicSession.unsubscribe("PVTEST");

        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            // close the queue connection
            if (topicConnection != null) {
                try {
                    topicConnection.close();
                } catch (Exception e) {
                    e.printStackTrace();
                }

            }
        }
    }

    /**
     * @return the clientId
     */
    public String getClientId() {
        return clientId;
    }

    /**
     * @param clientId the clientId to set
     */
    public void setClientId(String clientId) {
        this.clientId = clientId;
    }
}





weblogic.jms.common.InvalidClientIDException

This is what you get when you try to create 2 TopicConnection with the same ClientID:


Exception in thread "main" weblogic.jms.common.InvalidClientIDException: Client id, PVTEST_ID, is in use. The reason for rejection is "The JNDI name weblogic.jms.connection.clientid.PVTEST_ID was found, and was bound to an object of type weblogic.jms.frontend.FEClientIDSingularAggregatable : FEClientIDSingularAggregatable(SingularAggregatable(<3366864250607130900.1>:672):PVTEST_ID)"


at weblogic.jms.dispatcher.DispatcherAdapter.convertToJMSExceptionAndThrow(DispatcherAdapter.java:110)
at weblogic.jms.dispatcher.DispatcherAdapter.dispatchSync(DispatcherAdapter.java:45)
at weblogic.jms.client.JMSConnection.setClientID(JMSConnection.java:632)
at weblogic.jms.client.WLConnectionImpl.setClientID(WLConnectionImpl.java:602)
at durablesubscribers.Main.main(Main.java:46)

This is the offending code, at line 46:

TopicConnectionFactory qcf = (TopicConnectionFactory) ctx.lookup( "cf.epos.ho.01.nonXA.01" );
System.out.println("createTopicConnection");
topicConnection = qcf.createTopicConnection();
// must specify, otherwise you get an IllegalStateException
topicConnection.setClientID("PVTEST_ID");


Creating Durable Subscribers for a Distributed Topic

I need to run a stress test for a DT with >100 Durable Subscribers.

The Connection Factory to connect to the DT is registered in JNDI as a weblogic.jms.client.JMSConnectionFactory which implements javax.jms.QueueConnectionFactory AND javax.jms.TopicConnectionFactory (and some other interfaces)

A TopicConnectionFactory creates a TopicConnection,
which creates a TopicSession, which creates a Durable Subscriber identified with a name. This Durable Subscriber is a TopicSubscriber.




A TopicSubscriber is a MessageConsumer


Funnily enough, with WebLogic console you can examine only Durable Subscribers to a Distributed Topic is you are in a standalone server, but if you are in a cluster this Monitoring page is not available. You must write a WLST script for that.



Now, pay attention to this: when you create a Distributed Topic, with JNDI name "BLA", and you target it to 2 members, say JMSServer1 and JMSServer2, you get 2 different kind of entries in JNDI tree:

BLA = weblogic.jms.common.DistributedDestinationImpl

and
JMSServer1@BLA = weblogic.jms.common.DestinationImpl
JMSServer2@BLA = weblogic.jms.common.DestinationImpl


Be aware that YOU CANNOT CREATE A DURABLE SUBSCRIBER to a DistributedDestinationImpl, it must be a DestinationImpl.
So, lookup JMSServer1@BLA in JNDI, and not BLA.

java.util.MissingResourceException: No localizer class found for message id

While executing this code:

TopicConnectionFactory qcf = (TopicConnectionFactory) ctx.lookup( "my.connection.factory" );
TopicConnection topicConnection = qcf.createTopicConnection();


the thread hangs for 1 minute and then I get this great stacktrace:

Exception in thread "main" java.util.MissingResourceException: No localizer class found for message id.
at weblogic.i18ntools.L10nLookup.getLocalizer(L10nLookup.java:260)
at weblogic.i18ntools.L10nLookup.getLocalizer(L10nLookup.java:212)
at weblogic.i18n.logging.Loggable.getMessage(Loggable.java:183)
at weblogic.i18n.logging.Loggable.getMessage(Loggable.java:207)
at weblogic.jms.common.JMSException.(JMSException.java:66)
at weblogic.jms.client.JMSConnectionFactory.setupJMSConnection(JMSConnectionFactory.java:258)
at weblogic.jms.client.JMSConnectionFactory.createConnectionInternal(JMSConnectionFactory.java:285)
at weblogic.jms.client.JMSConnectionFactory.createTopicConnection(JMSConnectionFactory.java:184)
at durablesubscribers.Main.main(Main.java:43)


I am running it using the classpath with
wlclient.jar and javax.jms_1.1.1.jar


The exception was due to the fact that I was trying to create a Durable Subscriber to a Distributed Topic, and not to an individual member...

Anyway L10nLookup needs i18n_user.properties and weblogic/i18n/i18n.properties in the classpath. These files are included in most WebLogic modules (jars).

Tuesday, September 20, 2011

WebLogic server slow to start

If it hangs on
"Waiting to synchronize with other running members of mycluster"

check for instance:

member-warmup-timeout-seconds

maybe the cluster is slow to startup

On Unix, try using the property
"-Djava.security.egd=file:///dev/./urandom"



Genesys of a Patch

Put your patch JAR in
C:\pierre\bea103\utils\bsu\cache_dir
The JAR should have a 4 letter DNA, like I85X.jar
This jar contains a patch-descriptor.xml and a bugXXXXXXXXX.jar

Run C:\pierre\bea103\utils\bsu\bsu.cmd
Go on offline mode
Select a patch and "apply"



This will unzip the bugXXXXXXXXX.jar
to C:\pierre\bea103\patch_wls1030\patch_jars

and in C:\pierre\bea103\patch_wls1030\registry it will update a patch-registry.xml with a new patchInstallEntry

It will also update the manifest.mf in C:\pierre\bea103\patch_wls1030\profiles\default\sys_manifest_classpath\weblogic_patch.jar

(this weblogic_patch.jar contains nothing but a manifest.mf file, its only purpose is to "include" the patches in the System Classpath when we start WLS)

Probably all this will disappear with time as Oracle pushes a different Opatch tool - I don't know really. I was simply curious to understand how the patching mechanism works.

Redelivery of faulty JMS messages can bring a server to its knees

This morning CPU 200% and 100MB logs a minute.

A quick examination shows this:

WliSbTransports BEA-381502

Exception in JmsInboundMDB.onMessage: com
.bea.wli.sb.transports.TransportException: Unexpected type of message received: weblogic.jms.common.ObjectMessageImpl

No message redelivery limit was set, so the faulty messages were simply being redeliveder immediately several times a second.

Impossible to delete messages, because they were constantly in "receive" or "receive transaction" state.

Only way out: go to JMSServer, Monitoring, pause Consumption on all queues,
go to the queues, Monitoring, select messages and delete all.

And, of course, set a redelivery limit on the queues.

nmConnect, nmStart, nmKill

cd C:\bea103\wlserver_10.3\server\bin
setWLSEnv.cmd

java weblogic.WLST




nmConnect('weblogic', 'weblogic', 'localhost', '5556', 'base_domain', 'C:/bea103/user_projects/domains/base_domain', 'plain')


WLSTException: Error occured while performing nmConnect : Cannot connect to Node Manager.Unexpected response from server: § ? ??F


of course! 5556 is the port for 'ssl', and I was trying to use 'plain' !


nmConnect('weblogic', 'weblogic', 'localhost', '5556', 'base_domain', 'C:/bea103/user_projects/domains/base_domain', 'ssl')

WLSTException: Error occured while performing nmConnect : Cannot connect to Node Manager.Access to domain 'base_domain' for user '
weblogic' denied


edit C:\bea103\user_projects\domains\base_domain\config\nodemanager\nm_password.properties

and enter
username=weblogic
password=weblogic


nmConnect('weblogic', 'weblogic', 'localhost', '5556', 'base_domain', 'C:/bea103/user_projects/domains/base_domain', 'ssl')
Connecting to Node Manager ...
Successfully Connected to Node Manager.

wls:/nm/base_domain> nmStart('AdminServer', 'C:/bea103/user_projects/domains/base_domain')
Starting server AdminServer ...
Error Starting server AdminServer: weblogic.nodemanager.NMException: Exception while starting server 'AdminServer': java.io.IOException: Server failed to start up. See server output log for more details.

the log says:

weblogic.security.SecurityInitializationException: Authentication for user denied


so edit C:\bea103\user_projects\domains\base_domain\servers\AdminServer\security\boot.properties

and enter
username=weblogic
password=weblogic

Monday, September 19, 2011

Handy settings for your Unix environment

very few things are as frustrating as having to work on a Unix Shell which doesn't have autocomplete and history retrieve enabled, or the backspace.

Here are the settings:

stty erase ^? # backspace here
set -o emacs
alias __A=$(print '\0020') # ^P = up = previous command
alias __B=$(print '\0016') # ^N = down = next command
alias __C=$(print '\0006') # ^F = right = forward a character
alias __D=$(print '\0002') # ^B = left = back a character
alias __H=$(print '\0001') # ^A = home = beginning of line

I am still looking for autocompletion, my shell is /sbin/sh


And remember that ESC-ESC enables autocompletion in HP-UX - like TAB in Linux

Sunday, September 18, 2011

org.apache.log4j.net.SMTPAppender

there is a lovely way to send an alert by email using log4j:
just create an appender email of type SMTPAppender:


log4j.appender.email=org.apache.log4j.net.SMTPAppender
log4j.appender.email.SMTPHost=mailgateway.mycompany.com
log4j.appender.email.BufferSize=128
log4j.appender.email.To=myself@rabiddog.com
log4j.appender.email.Subject=My Subject Here
log4j.appender.email.layout=org.apache.log4j.HTMLLayout
log4j.appender.email.layout.ConversionPattern= [%t]: %m%n

BEA-000394 DEADLOCK DETECTED

Some days ago a managed server went boom crash bang during a restart,
and there was an elegant message warning us of a deadlock.

It's a lovely feature, but I still need to understand which service is monitoring the thread health.


<Sep 14, 2011 9:29:27 AM BST> <Critical> <WebLogicServer> <BEA-000394> <



DEADLOCK DETECTED:

==================



[deadlocked thread] [ACTIVE] ExecuteThread: '199' for queue: 'weblogic.kernel.Default (self-tuning)':

----------------------------------------------------------------------------------------------------

Thread '[ACTIVE] ExecuteThread: '199' for queue: 'weblogic.kernel.Default (self-tuning)'' is waiting to acquire lock 'java.util.concurrent.ConcurrentHashMap@d084be' that is held by thread '[ACTIVE] ExecuteThread: '15' for queue: 'weblogic.kernel.Default (self-tuning)''



Stack trace:

------------

weblogic.jndi.internal.BasicNamingNode.unbindHere(BasicNamingNode.java:587)

weblogic.jndi.internal.ServerNamingNode.unbindHere(ServerNamingNode.java:328)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:561)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.WLEventContextImpl.unbind(WLEventContextImpl.java:173)

weblogic.messaging.common.PrivilegedActionUtilities$4.run(PrivilegedActionUtilities.java:102)

weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)

weblogic.security.service.SecurityManager.runAs(Unknown Source)

weblogic.messaging.common.PrivilegedActionUtilities.unbindAsSU(PrivilegedActionUtilities.java:99)

weblogic.jms.common.SingularAggregatableManager.singularUnbind(SingularAggregatableManager.java:396)

weblogic.jms.frontend.FEConnection.removeClientID(FEConnection.java:387)

weblogic.jms.frontend.FEConnection.close(FEConnection.java:551)

weblogic.jms.frontend.FEConnection.normalClose(FEConnection.java:404)

weblogic.jms.frontend.FEConnection.invoke(FEConnection.java:1623)

weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)

weblogic.messaging.dispatcher.DispatcherServerRef.invoke(DispatcherServerRef.java:276)

weblogic.messaging.dispatcher.DispatcherServerRef.handleRequest(DispatcherServerRef.java:141)

weblogic.messaging.dispatcher.DispatcherServerRef.access$000(DispatcherServerRef.java:34)

weblogic.messaging.dispatcher.DispatcherServerRef$2.run(DispatcherServerRef.java:111)

weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)

weblogic.work.ExecuteThread.run(ExecuteThread.java:173)



[deadlocked thread] [ACTIVE] ExecuteThread: '15' for queue: 'weblogic.kernel.Default (self-tuning)':

---------------------------------------------------------------------------------------------------

Thread '[ACTIVE] ExecuteThread: '15' for queue: 'weblogic.kernel.Default (self-tuning)'' is waiting to acquire lock 'weblogic.cluster.ServiceAdvertiser@112bb58' that is held by thread '[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)''



Stack trace:

------------

weblogic.cluster.ServiceAdvertiser.announceReplacement(ServiceAdvertiser.java:132)

weblogic.cluster.ServiceAdvertiser.retractService(ServiceAdvertiser.java:95)

weblogic.jndi.internal.ServerNamingNode.advertiseUnbinding(ServerNamingNode.java:347)

weblogic.jndi.internal.ServerNamingNode.unbindHere(ServerNamingNode.java:330)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:561)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.BasicNamingNode.unbind(BasicNamingNode.java:573)

weblogic.jndi.internal.WLEventContextImpl.unbind(WLEventContextImpl.java:173)

weblogic.messaging.common.PrivilegedActionUtilities$4.run(PrivilegedActionUtilities.java:102)

weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)

weblogic.security.service.SecurityManager.runAs(Unknown Source)

weblogic.messaging.common.PrivilegedActionUtilities.unbindAsSU(PrivilegedActionUtilities.java:99)

weblogic.jms.common.SingularAggregatableManager.singularUnbind(SingularAggregatableManager.java:396)

weblogic.jms.common.SingularAggregatableManager.aggregatableDidBind(SingularAggregatableManager.java:479)

weblogic.jms.common.SingularAggregatable.onBind(SingularAggregatable.java:167)

weblogic.jndi.internal.BasicNamingNode.bindHere(BasicNamingNode.java:371)

weblogic.jndi.internal.ServerNamingNode.bindHere(ServerNamingNode.java:140)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:317)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.WLEventContextImpl.bind(WLEventContextImpl.java:277)

weblogic.cluster.BasicServiceOffer.install(BasicServiceOffer.java:101)

weblogic.cluster.NodeInfo.install(NodeInfo.java:62)

weblogic.cluster.TreeManager.install(TreeManager.java:59)

weblogic.cluster.MemberServices.processOffer(MemberServices.java:64)

weblogic.cluster.RemoteMemberInfo.processAnnouncement(RemoteMemberInfo.java:297)

weblogic.cluster.AnnouncementManager$1.run(AnnouncementManager.java:195)

weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)

weblogic.security.service.SecurityManager.runAs(Unknown Source)

weblogic.cluster.AnnouncementManager.receiveAnnouncement(AnnouncementManager.java:186)

weblogic.cluster.AnnouncementMessage.execute(AnnouncementMessage.java:26)

weblogic.cluster.MulticastReceiver$1.run(MulticastReceiver.java:112)

weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)

weblogic.work.ExecuteThread.run(ExecuteThread.java:173)



[deadlocked thread] [ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)':

--------------------------------------------------------------------------------------------------

Thread '[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'' is waiting to acquire lock 'weblogic.cluster.NodeInfo@719870' that is held by thread '[ACTIVE] ExecuteThread: '15' for queue: 'weblogic.kernel.Default (self-tuning)''



Stack trace:

------------

weblogic.cluster.NodeInfo.install(NodeInfo.java:61)

weblogic.cluster.TreeManager.install(TreeManager.java:59)

weblogic.cluster.MemberServices.processOffer(MemberServices.java:64)

weblogic.cluster.AnnouncementManager.announce(AnnouncementManager.java:126)

weblogic.cluster.ServiceAdvertiser.announceOffer(ServiceAdvertiser.java:111)

weblogic.cluster.ServiceAdvertiser.offerService(ServiceAdvertiser.java:71)

weblogic.cluster.ServiceAdvertiser.offerService(ServiceAdvertiser.java:46)

weblogic.jndi.internal.ServerNamingNode.advertiseBinding(ServerNamingNode.java:156)

weblogic.jndi.internal.ServerNamingNode.bindHere(ServerNamingNode.java:142)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:317)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.BasicNamingNode.bind(BasicNamingNode.java:324)

weblogic.jndi.internal.WLEventContextImpl.bind(WLEventContextImpl.java:277)

weblogic.messaging.common.PrivilegedActionUtilities$3.run(PrivilegedActionUtilities.java:78)

weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)

weblogic.security.service.SecurityManager.runAs(Unknown Source)

weblogic.messaging.common.PrivilegedActionUtilities.bindAsSU(PrivilegedActionUtilities.java:75)

weblogic.jms.common.SingularAggregatableManager.singularBindFinish(SingularAggregatableManager.java:325)

weblogic.jms.frontend.FEConnection.setConnectionClientId(FEConnection.java:1165)

weblogic.jms.frontend.FEConnection.invoke(FEConnection.java:1613)

weblogic.messaging.dispatcher.Request.wrappedFiniteStateMachine(Request.java:961)

weblogic.messaging.dispatcher.DispatcherServerRef.invoke(DispatcherServerRef.java:276)

weblogic.messaging.dispatcher.DispatcherServerRef.handleRequest(DispatcherServerRef.java:141)

weblogic.messaging.dispatcher.DispatcherServerRef.access$000(DispatcherServerRef.java:34)

weblogic.messaging.dispatcher.DispatcherServerRef$2.run(DispatcherServerRef.java:111)

weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)

weblogic.work.ExecuteThread.run(ExecuteThread.java:173)



>

Pack and unpack

cd C:\Oracle2\Middleware\wlserver_10.3\common\bin

pack -domain="c:\Oracle2\Middleware\user_projects\domains\osb_domain" -template="c:\temp\fanculo.jar" -template_name="template1" -managed=true

read domain from "C:\Oracle2\Middleware\user_projects\domains\osb_domain"
succeed: read domain from "C:\Oracle2\Middleware\user_projects\domains\osb_domain"
set config option Managed to "true"
succeed: set config option Managed to "true"
write template to "C:\temp\fanculo.jar"
....................................................................................................
succeed: write template to "C:\temp\fanculo.jar"
close template
succeed: close template




unpack -template="c:\temp\fanculo.jar" -domain="c:\Oracle2\Middleware\user_projects\domains\fanculo_domain"

read template from "C:\temp\fanculo.jar"
succeed: read template from "C:\temp\fanculo.jar"
set config option DomainName to "osb_domain"
succeed: set config option DomainName to "osb_domain"
write Domain to "C:\Oracle2\Middleware\user_projects\domains\fanculo_domain"
warning:write Domain to "C:\Oracle2\Middleware\user_projects\domains\fanculo_domain"
The "JDBC" configuration in your domain is invalid. Try to resolve the issue by reviewing your script. The wizard will continue, but you may want to start the server in the domain and review the messages to identify the invalid configuration.
...............................................................................................
succeed: write Domain to "C:\Oracle2\Middleware\user_projects\domains\fanculo_domain"
close template
succeed: close template

cd C:\Oracle2\Middleware\user_projects\domains\fanculo_domain
startWebLogic.cmd


C:\Oracle2\Middleware\user_projects\domains\fanculo_domain\config\config.xml not found

No config.xml was found.
Would you like the server to create a default configuration and boot? (y/n): n
18-Sep-2011 14:30:47 o'clock BST Critical WebLogicServer BEA-000362 Server failed. Reason:

There are 1 nested errors:

weblogic.management.internal.InteractiveConfigurationException: C:\Oracle\Middleware\user_projects\domains\fanculo_domain\config\config.xml not found.


I have really no clue what was wrong in my JDBC configuration....

Anyway later I realized I am an idiot: if you specify "managed=true", your config.xml will not be included in the domain template. You must specify "managed=false" to recreate the entire domain. JDBC error apart (I had to remove manually the DS) things work.

The official documentation is here:


http://download.oracle.com/docs/cd/E13179_01/common/docs103/pack/commands.html


Saturday, September 17, 2011

Pat O'Patch and Billy OUI

OUI=Oracle Universal Installer


http://download.oracle.com/docs/cd/B19306_01/em.102/b16227/toc.htm


I am catching up with the OPatch utility - we old fat obsolete BEA guys are still dreaming of the old bsu days, but reality steps forward and either you evolve or you die.

What we learn is that:

- there is a opatch utility, actually many:
C:\Oracle2\Middleware\oracle_common\OPatch\opatch.bat
C:\Oracle2\Middleware\Oracle_OSB1\OPatch\opatch.bat
C:\Oracle2\Middleware\Oracle_SOA1\OPatch\opatch.bat

- pick the one you like, I have tried C:\Oracle2\Middleware\Oracle_OSB1\.
You can try running it with
opatch

and you get a great help screen.
You might have to do
set ORACLE_HOME=C:\Oracle2\Middleware\oracle_common

or some other directory which contains a "oui" folder, otherwise you get a message

"The Oracle Home C:\Oracle2\MIDDLE~1 is not OUI based home. Please give proper Oracle Home.
OPatch returns with error code = 1

OPatch succeeded.
"

which is a weird way to succeed.


- if you manage to make "opatch lsinventory" work on Windows 64 please call me, because I keep getting

"java.lang.UnsatisfiedLinkError: Can't load library: C:/Oracle2/Middleware/Oracle_OSB1/oui/lib/win32/oraInstaller.dll
at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1702)"

I am sure I have messed up my installation.


- anyway there is a C:\Program Files\Oracle\Inventory\ContentsXML\inventory.xml which contains a list of all Oracle product Homes, mines are actually duplicated

- Big Brother is watching you: C:\Oracle2\Middleware\Oracle_OSB1\cfgtoollogs\ contains a history of every command you issued for opatch (opatch_history.txt) and oui

- What is your ARU_ID?
Each platform is identified by a platform id: you can see it in inventory.xml and in oraclehomeproperties.xml

Thursday, September 15, 2011

More on Debugging SAF on WebLogic

see here my previous post


Enable all the SAF debugging flags. All the Debug messages belong to the JMSSAF group.

When the remote destination (a Distributed Queue) becomes unavaliable, you should see - in the same Execute Thread:

Forwarder is trying to forward the message <703961.1316088865392.0>ddExactlyOnceForwardHelper= weblogic.jms.forwarder.Forwarder$Subforwarder$DDExactlyOnceForwardHelper@1e2d461

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: loadBlance() for message = <703961.1316088865392.0>

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: loadBalance()for sequence number :124

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: loadbalance() : failedDDMeberInfo=<DDMemnerInoImpl> = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer

DDLBTableImpl: removeFailedDDMemberInfo():  sequenceNumber= 124


weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: findOrCreateDestination() :  ddMeberInfo= = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer} dImpl =MyJMSModule!MyJMSServer@MyQueue

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: findOrCreateDestination() :  dImpl.isStale= truedImpl.id= <2267211883542783366.18>

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: findOrCreateDestination() :  about to create javax.jms.Queue for MyJMSServer/MyJMSModule!MyJMSServer@MyQueue


and then a fantastic

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: loadbalance() : failed 
weblogic.jms.common.LostServerException: [JMSClientExceptions:055169]Network connection to server was lost.
 at weblogic.jms.client.JMSSession.checkClosed(JMSSession.java:4771)
 at weblogic.jms.client.JMSSession.createDestination(JMSSession.java:3116)
 at weblogic.jms.client.JMSSession.createQueue(JMSSession.java:2514)
 at weblogic.jms.client.WLSessionImpl.createQueue(WLSessionImpl.java:938)
 at weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl.findOrCreateDestination(DDLoadBalancerDelegateImpl.java:289)
 at weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl.loadBalance(DDLoadBalancerDelegateImpl.java:193)
 at weblogic.jms.forwarder.Forwarder$Subforwarder$DDExactlyOnceForwardHelper.getEndpoint(Forwarder.java:1124)
 at weblogic.jms.forwarder.Forwarder$Subforwarder.getEndpoint(Forwarder.java:1037)
 at weblogic.jms.forwarder.Forwarder$Subforwarder.forward(Forwarder.java:745)
 at weblogic.jms.forwarder.Forwarder$Subforwarder.pushMessages(Forwarder.java:676)
 at weblogic.messaging.util.DeliveryList.run(DeliveryList.java:263)
 at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:516)
 at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
 at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
Caused by: weblogic.jms.common.LostServerException: server connection in state STATE_NO_RETRY
 at weblogic.jms.client.ReconnectController.attachReasonToException(ReconnectController.java:609)
 at weblogic.jms.client.ReconnectController.analyzeExceptionAndReconnect(ReconnectController.java:540)
 at weblogic.jms.client.ReconnectController.computeJMSSession(ReconnectController.java:630)
 at weblogic.jms.client.WLSessionImpl.createQueue(WLSessionImpl.java:945)
 ... 10 more
Caused by: weblogic.jms.common.LostServerException: java.lang.Exception: weblogic.rjvm.PeerGoneException: ; nested exception is: 
 java.io.EOFException
 at weblogic.jms.client.JMSConnection.dispatcherPeerGone(JMSConnection.java:1436)
 at weblogic.messaging.dispatcher.DispatcherWrapperState.run(DispatcherWrapperState.java:692)
 at weblogic.messaging.dispatcher.DispatcherWrapperState.timerExpired(DispatcherWrapperState.java:617)
 at weblogic.timers.internal.TimerImpl.run(TimerImpl.java:273)
 ... 3 more
Caused by: java.lang.Exception: weblogic.rjvm.PeerGoneException: ; nested exception is: 
 java.io.EOFException
 at weblogic.messaging.dispatcher.DispatcherWrapperState.onDisconnect(DispatcherWrapperState.java:396)
 at weblogic.rjvm.RJVMImpl$DisconnectEventDeliverer.run(RJVMImpl.java:1647)
 ... 3 more
Caused by: weblogic.rjvm.PeerGoneException: ; nested exception is: 
 java.io.EOFException
 at weblogic.rjvm.RJVMImpl.gotExceptionReceiving(RJVMImpl.java:957)
 at weblogic.rjvm.ConnectionManager.gotExceptionReceiving(ConnectionManager.java:1036)
 at weblogic.rjvm.MsgAbbrevJVMConnection.gotExceptionReceiving(MsgAbbrevJVMConnection.java:459)
 at weblogic.rjvm.t3.MuxableSocketT3.endOfStream(MuxableSocketT3.java:337)
 at weblogic.socket.SocketMuxer.deliverExceptionAndCleanup(SocketMuxer.java:793)
 at weblogic.socket.SocketMuxer.deliverEndOfStream(SocketMuxer.java:727)
 at weblogic.socket.NTSocketMuxer.processSockets(NTSocketMuxer.java:92)
 at weblogic.socket.SocketReaderRequest.run(SocketReaderRequest.java:29)
 at weblogic.socket.SocketReaderRequest.execute(SocketReaderRequest.java:42)
 at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:145)
 at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:117)
Caused by: java.io.EOFException
 ... 8 more



and then


DDLBTableImpl: addFailedDDMemberInfo(): sequenceNumber= 124 ddMemberInfo = = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer}


Forwarder is trying to forward the message with id <703961.1316088865392.0> to MyJMSModule!MyJMSServer@MyQueue

Forwarder failed to forward the message TextMessage[ID:<703961.1316088865392.0>, 33|1|0|0|0|0|0|0|0|0|0|0|0|0|0...] to MyJMSModule!MyJMSServer@MyQueue stopPipeline= false hasNonFailedDDMembers true isExactlyOnceDDForwarding true failureCount 0
weblogic.jms.common.LostServerException: [JMSClientExceptions:055169]Network connection to server was lost.
at weblogic.jms.client.JMSProducer.checkClosed(JMSProducer.java:1085)
at weblogic.jms.client.JMSProducer.publicCheckClosed(JMSProducer.java:1090)
at weblogic.jms.client.ReconnectController.checkClosedReconnect(ReconnectController.java:678)
at weblogic.jms.client.WLProducerImpl.checkClosedReconnectGetProducer(WLProducerImpl.java:57)
at weblogic.jms.client.WLProducerImpl.checkClosedReconnectGetProducer(WLProducerImpl.java:60)
at weblogic.jms.client.WLProducerImpl.getUnitOfOrder(WLProducerImpl.java:479)


Negatively acknowledging 1 messages with delay 5000



DDLBTableImpl: addFailedDDMemberInfo(): sequenceNumber= 124 ddMemberInfo = = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer}

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: removeDestination() : ddMemberInfo = = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer} persist=true

weblogic.jms.forwarder.dd.internal.DDLoadBalancerDelegateImpl@16a4d0a: persistLoadBalancerInfo() : event = 2 ddMemberInfo= = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer}

DDLBTableImpl: removeDDMemberInfo(): ddMemberInfo= = { ddMemberConfigName=MyJMSModule!MyJMSServer@MyQueue, destinationType=javax.jms.Queue, JmsServerName=MyJMSServer}

checkSAFClosed got JMSException:
weblogic.jms.common.IllegalStateException: [JMSClientExceptions:055076]The session is closed
at weblogic.jms.client.JMSSession.checkSAFClosed(JMSSession.java:4780)
at weblogic.jms.client.WLSessionImpl.checkSAFClosed(WLSessionImpl.java:235)
at weblogic.jms.forwarder.Forwarder$Subforwarder.handleForwardFailure(Forwarder.java:976)
at weblogic.jms.forwarder.Forwarder$Subforwarder.forward(Forwarder.java:757)
at weblogic.jms.forwarder.Forwarder$Subforwarder.pushMessages(Forwarder.java:676)
at weblogic.messaging.util.DeliveryList.run(DeliveryList.java:263)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:516)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

Forwarder connectTarget()

Wednesday, September 14, 2011

XA resources and Transaction Timeout

Interesting case:

We had a couple of JMS messages stuck in a queue, and CPU 100%.

JMS message state: receive transaction

JMSXDeliveryCount 2060

The transactions were of very long duration, above 100 seconds, and they would end with an application rollback (not a Timeout Rollback):


####<Sep 13, 2011 12:00:12 AM BST> <Error> <EJB> <myserver.unix.acme.com> <pluto_AdminServer> <[ACTIVE] ExecuteThread: '11' for queue: 'weblogic.kernel.Default (self-tuning)'> <<anonymous>> <> <> <1315868412458> <BEA-010026> <Exception occurred during commit of transaction Xid=BEA1-556D788B8665743465EB(33150705),Status=Rolled back. [Reason=oracle.jdbc.xa.OracleXAException],numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since begin=124,seconds left=60,XAServerResourceInfo[WLStore_pluto01_Domain__WLS_pluto_AdminServer]=(ServerResourceInfo[WLStore_pluto01_Domain__WLS_pluto_AdminServer]=(state=rolledback,assigned=pluto_AdminServer),xar=WLStore_pluto01_Domain__WLS_pluto_AdminServer28341129,re-Registered = false),XAServerResourceInfo[rmsscottish]=(ServerResourceInfo[rmsscottish]=(state=rolledback,assigned=pluto_AdminServer),xar=rmsscottish,re-Registered = false),SCInfo[pluto01_Domain+pluto_AdminServer]=(state=rolledback),local properties=({weblogic.jdbc.jta.rmsscottish=[ No XAConnection is attached to this TxInfo ]}),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=pluto_AdminServer+10.3.75.186:7001+pluto01_Domain+t3+, XAResources={WLStore_pluto01_Domain__WLS_pluto_AdminServer, WLStore_pluto01_Domain_FileStore, WLStore_pluto01_Domain_WseeFileStore, rmsscottish},NonXAResources={})],CoordinatorURL=pluto_AdminServer+10.3.75.186:7001+pluto01_Domain+t3+): weblogic.transaction.RollbackException: Could not prepare resource 'rmsscottish
at weblogic.transaction.internal.TransactionImpl.throwRollbackException(TransactionImpl.java:1818)
at weblogic.transaction.internal.ServerTransactionImpl.internalCommit(ServerTransactionImpl.java:336)
at weblogic.transaction.internal.ServerTransactionImpl.commit(ServerTransactionImpl.java:230)
at weblogic.ejb.container.internal.MDListener.execute(MDListener.java:500)
at weblogic.ejb.container.internal.MDListener.transactionalOnMessage(MDListener.java:371)
at weblogic.ejb.container.internal.MDListener.onMessage(MDListener.java:327)
at weblogic.jms.client.JMSSession.onMessage(JMSSession.java:4547)
at weblogic.jms.client.JMSSession.execute(JMSSession.java:4233)
at weblogic.jms.client.JMSSession.executeMessage(JMSSession.java:3709)
at weblogic.jms.client.JMSSession.access$000(JMSSession.java:114)
at weblogic.jms.client.JMSSession$UseForRunnable.run(JMSSession.java:5058)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:516)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
Caused by: oracle.jdbc.xa.OracleXAException
at oracle.jdbc.xa.client.OracleXAResource.prepare(OracleXAResource.java:679)
at weblogic.jdbc.wrapper.VendorXAResource.prepare(VendorXAResource.java:70)
at weblogic.jdbc.jta.DataSource.prepare(DataSource.java:885)
at weblogic.transaction.internal.XAServerResourceInfo.prepare(XAServerResourceInfo.java:1277)
at weblogic.transaction.internal.XAServerResourceInfo.prepare(XAServerResourceInfo.java:500)
at weblogic.transaction.internal.ServerSCInfo$1.run(ServerSCInfo.java:361)
... 3 more
.>


The transaction monitoring page would say:


This page shows information about current transactions coordinated by the server or in which server resources participate.

Transaction statistics(Filtered - More Columns Exist)

Transaction ID Status Seconds Active XA Resources Servers

BEA1-004042C8BFB5743465EB Active 178 {myds=ended, WLStore_pluto01_Domain__WLS_pluto_AdminServer=suspended} {pluto01_Domain+pluto_AdminServer=active}

BEA1-004442C8BFB5743465EB Active 80 {myds=ended, WLStore_pluto01_Domain__WLS_pluto_AdminServer=suspended} {pluto01_Domain+pluto_AdminServer=active}



It turns out that the Proxy Service consuming the messages has "Force XA transaction" set to true, and myds was a Data Source with a JDBC driver XA compliant, hence it was enrolled in the transaction even if the DB was used only for a lookup.

I am persuaded that the DB was throwing an exception because it had already internally timed out the transaction (XA timeout is 60 seconds by default).

Replacing the JDBC driver with a non-XA avoided enrolling the DB in the XA transaction, hence no more rollbacks.

Incidentally when we first restarted the server, the transaction recovery service recovered the 2 previous transactions, and they got stuck because now the DS was not XA compliant any more. Restarting again fixed the problem, because all new transactions would not enroll the DB any more.

Interestingly, the JTA timeout at domain level is set to 30 seconds, but this timeout doesn't refer to the whole duration of the 2 Phase Commit transaction, it refers only to the "prepare" phase. So the Transactions can well last 100 seconds without JTA complaining about it. What you should look at is the "abandon timeout period" which is by default enormously high.

Pending XA Transactions on Oracle DB

With the statement:

SELECT formatid, globalid, branchid FROM SYS.DBA_PENDING_TRANSACTIONS;
select * from DBA_2PC_PENDING;
select * from V$GLOBAL_TRANSACTION


you should be able to extract info on the pending XA transactions.

This is an excellent document on the parameters regulating the timeout on Oracle DB with XA transactions


More interesting reading here:
http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28424/adfns_xa.htm


two-phase commit = prepare + commit, then forget


DEFAULT_XA_TIMEOUT = 60
XA_SETTIMEOUT defaults to 60
DISTRIBUTED_LOCK_TIMEOUT specifies the amount of time (in seconds) for distributed transactions to wait for locked resources.


Generally, these timeouts should be set in the following order:
1. TM’s global transaction timeout (or the JTA timeout) <
2. SesTm and SesWt (Transaction Timeout for JDBC or PL/SQL) <
3. DISTRIBUTED_LOCK_TIMEOUT <
4. Either of CONNECT_TIME or IDLE_TIME

Nice-to-activate Sun JVM flags for GC and ThreadDumps

-Xloggc:ms1gc.log

http://stackoverflow.com/questions/1161647/how-to-redirect-verbose-garbage-collection-output-to-a-file



-Xloggc is like -Xverbose:gc but it logs in a separate file ms1gc.log

It is safe to activate in production (unlike -Xprof which is quite taxing)


This is a list of options for the JVM:

http://download.oracle.com/javase/6/docs/technotes/tools/windows/java.html


Sample test of –Xloggc:



cat DoNothing.java


public class DoNothing {

   public static void main(String[] args) throws Exception {

       for (;;) {

           Thread.sleep(1000);
           int zillion = 1000000;
           // just wasting memory here
           Object[] waste = new Object[zillion];
           for (int i = 0; i < zillion; i++) {
              waste[i] = new Object();
           }

          // yield CPU, don’t be greedy
           System.out.println("I am just sleeping... how lovely....");
       }
   }
}
javac DoNothing.java java -Xloggc:mygc.log DoNothing cat mygc.log
5.629: [GC 47048K->120K(187712K), 0.0045328 secs]

9.769: [GC 47016K->128K(187712K), 0.0015663 secs]

13.889: [GC 47024K->136K(187712K), 0.0011926 secs]

18.009: [GC 47032K->136K(187712K), 0.0011626 secs]

22.129: [GC 47032K->136K(178560K), 0.0056787 secs]

26.259: [GC 47032K->136K(177408K), 0.0011921 secs]

29.371: [GC 46792K->11618K(187584K), 0.4040244 secs]

34.925: [GC 68450K->21588K(226688K), 0.3109225 secs]

43.478: [GC 111764K->22196K(229824K), 0.1426002 secs]

51.857: [GC 109907K->16082K(284544K), 0.0322680 secs]

64.259: [GC 156772K->16082K(284672K), 0.1478636 secs]

76.779: [GC 156772K->16082K(370560K), 0.0095127 secs]

96.393: [GC 246994K->24276K(370816K), 0.3453224 secs]

117.345: [GC 255188K->20740K(356672K), 0.0354717 secs]

136.948: [GC 238833K->16082K(343040K), 0.0122887 secs]

155.509: [GC 227101K->16082K(334464K), 0.0144088 secs]

Be aware that every time the JVM is started the previous mygc.log is overwritten. The very ridiculous thing is that there is no readable timestamp associated with the GC event….how silly! The times are reported as milliseconds from the JVM start time! So when we interpret these results we should first determine the start time of the JVM (this should not be an issue…) -XX:+PrintGCDetails -XX:+PrintGCDateStamps I have tried both, and PrintGCDetails is supported on Itanium:
5.665: [GC [PSYoungGen: 47048K->136K(57152K)] 47048K->136K(187712K), 0.0024533 secs]

9.795: [GC [PSYoungGen: 47032K->128K(57152K)] 47032K->128K(187712K), 0.0010407 secs]

13.926: [GC [PSYoungGen: 47024K->128K(57152K)] 47024K->128K(187712K), 0.0010135 secs]

18.044: [GC [PSYoungGen: 47024K->128K(57152K)] 47024K->128K(187712K), 0.0010428 secs]

22.165: [GC [PSYoungGen: 47024K->136K(48000K)] 47024K->136K(178560K), 0.0080463 secs]

Heap

 PSYoungGen      total 48000K, used 11948K [5dab0000, 61290000, 73000000)

  eden space 47808K, 24% used [5dab0000,5e6390e0,60960000)

  from space 192K, 70% used [60a90000,60ab2050,60ac0000)

  to   space 192K, 0% used [61260000,61260000,61290000)

 PSOldGen        total 130560K, used 0K [33000000, 3af80000, 5dab0000)

  object space 130560K, 0% used [33000000,33000000,3af80000)

 PSPermGen       total 16384K, used 1820K [2f000000, 30000000, 33000000)

  object space 16384K, 11% used [2f000000,2f1c7168,30000000)


but PrintGCDateStamps is NOT (:o( ) Anyway XX options are not recommended for production system

See here http://stackoverflow.com/questions/541832/know-of-any-java-garbage-collection-log-analysis-tools for a list of tools to analyze GC logs

Here http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html a list of XX options

I have also tested this flag: -XX:+PrintConcurrentLocks
and it prints in the threadDump very valuable information on the locks being held by each thread:

Example:
java -Xloggc:mygc.log -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintConcurrentLocks -XX:+PrintGCTimeStamps DoNothing

I do a kill -3 on the PID, and I get this on the stdout:

Full thread dump Java HotSpot(TM) Server VM (1.6.0.01 jinteg:06.07.08-04:50 IA64 mixed mode):

"Low Memory Detector" daemon prio=5 tid=00459790 nid=12 lwp_id=644290 runnable [00000000..00000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None


"CompilerThread1" daemon prio=9 tid=005e22e0 nid=10 lwp_id=644288 waiting on condition [00000000..2d7ff688]
   java.lang.Thread.State: RUNNABLE
 

   Locked ownable synchronizers:
        - None

"CompilerThread0" daemon prio=9 tid=005db1a0 nid=9 lwp_id=644287 waiting on condition [00000000..2dfff608]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" daemon prio=9 tid=00459590 nid=8 lwp_id=644286 waiting on condition [00000000..00000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:

        - None

"Finalizer" daemon prio=8 tid=00459390 nid=7 lwp_id=644283 in Object.wait() [733c0000..733c0b90]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        - waiting on <612802c0> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)

        - locked <612802c0> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)

        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:197)

 

   Locked ownable synchronizers:

        - None

 

"Reference Handler" daemon prio=10 tid=00459190 nid=6 lwp_id=644282 in Object.wait() [77540000..77540d10]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        - waiting on <61280350> (a java.lang.ref.Reference$Lock)

        at java.lang.Object.wait(Object.java:485)

        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:123)

        - locked <61280350> (a java.lang.ref.Reference$Lock)

 

   Locked ownable synchronizers:

        - None

 

"main" prio=5 tid=00458f90 nid=1 lwp_id=-1 waiting on condition [7fffe000..7fffe798]

   java.lang.Thread.State: TIMED_WAITING (sleeping)

        at java.lang.Thread.sleep(Native Method)

        at DoNothing.main(DoNothing.java:4)

 

   Locked ownable synchronizers:

        - None

 

"VM Thread" prio=9 tid=005a7860 nid=5 lwp_id=644281 runnable

 

"GC task thread#0 (ParallelGC)" prio=5 tid=004661f0 nid=3 lwp_id=644279 runnable

 

"GC task thread#1 (ParallelGC)" prio=5 tid=00466410 nid=4 lwp_id=644280 runnable

 

"VM Periodic Task Thread" prio=10 tid=005a7950 nid=11 lwp_id=644289 waiting on condition

 

JNI global references: 585

 

Heap

 PSYoungGen      total 57152K, used 39278K [5dab0000, 61a70000, 73000000)

  eden space 49024K, 79% used [5dab0000,600f3b38,60a90000)

  from space 8128K, 1% used [61280000,612a0040,61a70000)

  to   space 8128K, 0% used [60a90000,60a90000,61280000)

 PSOldGen        total 130560K, used 0K [33000000, 3af80000, 5dab0000)

  object space 130560K, 0% used [33000000,33000000,3af80000)

 PSPermGen       total 16384K, used 1797K [2f000000, 30000000, 33000000)

  object space 16384K, 10% used [2f000000,2f1c17d8,30000000)

This option is the default on JRockit… priceless!

Problem is that the XX options are not really recommended for production systems, so…


“Options that are specified with -XX are not stable and are not recommended for casual use. These options are subject to change without notice. “

Monday, September 12, 2011

Troubleshooting and Debugging WebLogic SAF

In the logs typically we shall find at startup:

<Info> <SAFService> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766521288> <BEA-281003> <SAF Service has been initialized.>

<Info> <SAFService> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766521300> <BEA-281002> <SAF Service has been started.>

<Info> <SAFService> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766522952> <BEA-281007> <SAF Agent "TESTSAFAgent@ms2" has been successfully prepared.>


<Info> <Store> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766522976> <BEA-280008> <Opening the persistent file store "filestore2" for recovery: directory=C:\Oracle2\Middleware\user_projects\domains\osb_domain\servers\ms2\data\store\filestore2 requestedWritePolicy="Direct-Write" fileLockingEnabled=true driver="wlfileio3".>

<Info> <Store> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523128> <BEA-280009> <The persistent file store "filestore2" (6664685f-2e2e-4a64-b87d-c9fc9e485ade) has been opened: blockSize=512 actualWritePolicy="Direct-Write(read-buffered)" explicitIOEnforced=false records=49.>

<Info> <JMS> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523135> <BEA-040321> <JMSServer "TESTSAFAgent@ms2" is resuming.>

<Info> <Messaging> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523212> <BEA-282003> <The messaging kernel TESTSAFAgent@ms2 will use up to 345,986,389 bytes of memory before paging begins>

<Info> <Messaging> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523226> <BEA-282001> <The messaging kernel TESTSAFAgent@ms2 is beginning recovery of its persistent state>

<Info> <Messaging> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523265> <BEA-282002> <The messaging kernel TESTSAFAgent@ms2 has recovered 0 persistent messages>

<Debug> <SAFStore> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523341> <BEA-000000> <*********** ***** <SAFStoreRecord> state= class=weblogic.messaging.saf.internal.SendingAgentImpl code=15 obj=<SendingAgentImpl> : SAFAgentInternalName = TESTSAFAgent@ms2 null>

<Debug> <SAFStore> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523341> <BEA-000000> < == SAFStore Created for Agent TESTSAFAgent@ms2.SA>

<Debug> <SAFSendingAgent> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523343> <BEA-000000> <Sending Agent 'TESTSAFAgent@ms2' has recovered 0 conversation infos>

<Debug> <SAFSendingAgent> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523343> <BEA-000000> <Sending Agent 'TESTSAFAgent@ms2' is starting: found 0 topics>

<Info> <SAFService> <pierrepc> <ms2> <[STANDBY] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766523343> <BEA-281008> <SAF Agent "TESTSAFAgent@ms2" has been successfully activated.>


<Info> <JMS> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315766539485> <BEA-040109> <JMSServer "TESTSAFAgent@ms2" is started.>




http://download.oracle.com/docs/cd/E12840_01/wls/docs103/saf_admin/troubleshoot.html




weblogic.diagnostics.debug.DebugLogger.DISABLED
weblogic.management.utils.debug

-Dweblogic.debug.DebugSAFSendingAgent=true
-Dweblogic.log.StdoutSeverity="Debug"



Server debug flags:

in the "default" area:
DebugMessaging
(remember to restart)

in the WebLogic area:
DebugSAFAdmin, DebugSAFLifeCycle, DebugSAFManager, DebugSAFMessagePath, DebugSAFReceivingAgent, DebugSAFSendingAgent, DebugSAFStore
DebugSAFTransport, DebugSAFVerbose, DebugJMSSAF, DebugMessagingKernel


Especially enabling DebugJMSSAF traces this info in the logs:

<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607231> <BEA-000000> <Forwarder reconnect(): remoteInitialCtx= null>
<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607231> <BEA-000000> <Forwarder connectTarget()>
<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607231> <BEA-000000> <Retry for 't3://pierrepc:7011' to 't3://pierrepc:7011'>
<Debug> <JMSSAF> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315778607232> <BEA-000000> <Forwarder::getInitialContext()::Password=XXXX,username=weblogic>


The DebugMessagingKernel produces a lot of info:


<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610966> <BEA-000000> <Queue SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 sending message element: [ sequence=0 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=0 deliveryCount=0 ] handle: [ id=3 queueRefCount=1 quotaRefCount=1 persistentRefCount=0 pinCount=1 size=5 persistent=true persistBody=false ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610967> <BEA-000000> <Added message to the queue list: [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=1 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=0 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610967> <BEA-000000> <Enlisting message [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=1 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=0 ] in transaction weblogic.store.gxa.internal.GXALocalTransactionImpl@80e605>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610975> <BEA-000000> <SendOperation prepare called for [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=5 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=0 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610978> <BEA-000000> <Persisted new value of 0 for sequence [ name=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 sequenceMode=ASSIGN destination=weblogic.messaging.kernel.internal.QueueImpl@8845ff03 lastValue=0 lastAssignedValue=9 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'> <weblogic> <> <> <1315779610983> <BEA-000000> <Persisted message element 3 to queue weblogic.messaging.kernel.internal.QueueImpl@8845ff03>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315779610987> <BEA-000000> <SendOperation commit called. Making message visible [ sequence=3 queue=1 name=SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2 state=261 deliveryCount=0 sequence=osb_domain@myCluster@ms2@SAFTestModule!SAFImportedDestinations0!SAFTESTLOCAL@TESTSAFAgent@ms2201109091356440079 number=10 ]>
<Debug> <MessagingKernel> <pierrepc> <ms2> <[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1315779610994> <BEA-000000> <Resuming send of message [ state = COMMIT handle = [ id=3 queueRefCount=1 quotaRefCount=1 persistentRefCount=1 pinCount=1 size=5 persistent=true persistBody=true ] ]>