PANIC with reply messages

[Paul Glezen]

I’ve been developing my first web service client using the CAA-WS adapter.  Things seemed to be going well.  But I ran into a snag yesterday afternoon just as I thought I had finished.  I had been running various tests all day long on my output thread (java/ws-client protocol) using SMAT to inject a message into the pre-TPS output.  The server, for now, is just SOAP-UI running a mock service that alternately returns success or fault so that I can test my error handling.

I have a Tcl proc handling the TPS Inbound Reply on the Outbound tab.  The Inbound tab is marked Outbound Only.  Things were going well.  Right before I left for the day, I added some logging code.  When I tried to restart the thread, the entire process crashed with PANIC messages.  I’ve never seen anything like it.  I couldn’t see any log messages about what caused the problem.

This morning I enabled full logging for the process.  I also unchecked the Auto-start Connection for the problem thread.  Now the process comes up fine with the other threads.  When I attempt to start the problem thread, the PANIC occurs.  With full logging enabled, I can see that there is some message processing going on with XML messages that I recognize from my testing the day before.  I thought that maybe I have some sort of infinite loop that causes a stack-overflow.  In fact, I suspect just such a thing because I started experimenting with Route Replies .  I route a reply back to the same thread that issued the WS client request.  I wondered if this was a problem.  I disabled these route replies along with most of my TPS scripts.  But the symptom persists.

Anyway, since right off the bat my problem thread starts attempting to process messages that were introduced yesterday, I considered cleaning out the recovery/error DB.  But when I queried these DBs with hcidbdump, none of the entries had my problem thread listed.  So I wondered if there is some other place where internal state about a process is maintained.

Below is a snippet of my log just as the PANIC occurs.  My problem thread is named gards_ob.

Code:

[pd  :thrd:INFO/1:     gards_ob:06/16/2016 07:41:41] [0.0.242261314] Discovered msg in state OB delivered OK
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Checking msg [0.0.242261317], owner ‘gards_ob’, state 1
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Message selected for callback
[dbi :log :DBUG/2:     gards_ob:06/16/2016 07:41:41] log context: type 1, dbn 1, msgRec 10001, mdRec 10002, bodyRec 10003
[msg :Msg :DBUG/0:     gards_ob:06/16/2016 07:41:41] msg_Alloc new message 0xefff4628
[msg :Mid :DBUG/0:     gards_ob:06/16/2016 07:41:41] mid free [0.0.242261317] 0x32e71e98
[dbi :log :DBUG/3:     gards_ob:06/16/2016 07:41:41] [0.0.242261317] got msg body, size = 1000
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–] msg: 0xefff4628
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgType           : REPLY
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgClass          : PROTOCOL
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgState          : IB pre-SMS (1)
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgPriority       : 5120
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgRecoveryDbState: Log:off (1)
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgFlags          : 0x8012
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgMid            : [0.0.242261317]
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgSrcMid         : midNULL
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgSrcMidGroup    : midNULL
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgHostId         : 995902887
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgOrigSrcThread  : gards_ob
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgOrigDestThread : gards_ob
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgSrcThread      : gards_ob
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgDestThread     : gards_ob
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgXlateThread    :
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgSkipXlate      : 0
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgSepChars       :
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgNumRetries     : 0
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgGroupId        : 0
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgDriverControl  :
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgRecordFormat   :
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgRoutes         :
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgUserData       : {httpResponseHeaders {{content-type text/xml; charset=utf-8} {Content-Length 267} {Server Jetty(
6.1.26)}}} {fault {{code {http://schemas.xmlsoap.org/soap/envelope/}Server} {faultString Just a test fault}}} {httpResponseCode 500}
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgStaticIsDirty  : 0
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgVariableIsDirty: 0
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgTimeStartIb    : 1466027570.383
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgTimeStartOb    : 1466027570.348
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgTimeCurQueStart: 1466027570.383
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgTimeTotalQue   : 0.000
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgTimeRecovery   : 1466027570.383
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgEoConfig       : 0x0
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     msgData (BO)      : 0xefff472c
[dbi :log :DBUG/3:     gards_ob:–/–/—- –:–:–]     message           : ‘soapenv:ServerJust a test
fault‘
[pd  :thrd:INFO/1:     gards_ob:06/16/2016 07:41:41] [0.0.242261317] Discovered msg in state IB pre-SMS
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Checking msg [0.0.242261415], owner ‘gard2_ob’, state 10
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Message not selected
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Checking msg [0.0.242261453], owner ‘gard2_ob’, state 10
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Message not selected
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Checking msg [0.0.242261480], owner ‘gard2_ob’, state 10
[dbi :log :INFO/3:     gards_ob:06/16/2016 07:41:41] Message not selected
[pd  :thrd:INFO/1:     gards_ob:06/16/2016 07:41:41] [0.0.242261227] Requeuing: date 1466022710.5195 in state OB delivered OK
[pd  :thrd:INFO/1:     gards_ob:06/16/2016 07:41:41] [0.0.242261234] Requeuing: date 1466022752.7206 in state OB delivered OK
PANIC: “(ptd)->ptd_msg_delivered_ok == ((Message *) 0)”
PANIC: Calling “pti” for thread gards_cmd
—– Scheduler State —–
Thread Events     State      Priority Runnable  PT Msgs
  0      0   SCHED_IDLE         0       0       0,0,0
  1      0   SCHED_IDLE         0       0       0,0,0
  2      0   SCHED_IDLE         0       0       0,0,0
  3      0   SCHED_IDLE         0       0       0,0,0
  4      0   SCHED_IDLE         0       0       0,0,0
  5      0   SCHED_IDLE         0       0       0,0,0

————– Thread 0 (gards_cmd)————–
ti: 0x30b5ffb8
   tid           :    0
   HostPthreadId : 0x1
   EventList     : 0x30b24ca8
   PolledEvents  : 0x30b24cc8
   PthreadEvent  : 0x30b6b258
   ReadyEvents   : 0x30b3cfa8
   CtrlMsgs      : 0x30b3cfc8
   UserCtrlMsgs  : 0x30b3cfe8
   UserDataMsgs  : 0x30b60108
   StartArgs     : 0x0
   SchedState    : SCHED_IDLE
   SchedPriority : 0
   Killed        : 0
—– Registered Events —–
el: 0x30b24ca8
   elCount : 3

There is a reference to gards2_ob.  That’s a thread in another process I created for an unrelated matter.

Topic

[Elisha Gould]

Are the CAA-WS threads in separate processes?

Cloverleaf does not have thread safe Java handling, so each Java proc must be in a separate process.

[Paul Glezen]

Yes, so far, I only have one CAA-WS thread in my process.  I intend to keep it that way due to the warnings in the CAA-WS documentation.

I suspect my problem is elementary.  I’m still new to Cloverleaf development and this is my first time playing with the CAA-WS API.  In particular, I’m not confident that I’m handling the reply messages properly.  I’m coding an outbound node calling a web service in order to notify the service of an event.  It’s simple in that I only have to check the response for a successful status code.  I don’t need to further process or forward the response payload to another destination.

One suspicion I have about my configuration is that I’m not assigning a disposition to the message I receive in the reply.  I’m still a bit fuzzy on how message dispositions work for inbound replies.  Should I include a disposition of CONTINUE for the reply message?  Or should I KILL it since a successful reply isn’t going anywhere?

Erroneous Information Alert  – In my previous post I said the error and recovery DBs showed no entries related to my problem thread.  That’s because I had my environment variable set to the wrong site.  After I corrected this, I found 15 message in the error DB and several dozen in the recovery DB.  I deleted all of it and I no longer receive the PANIC messages.

[Jim Kosloskey]

Typically a Reply which is not needed further is KILLed. The best place to do that is as early as possible once it is determined the Reply is good (not an Reply indicating some sort of error).

email: jim.kosloskey@jim-kosloskey.com 29+ years Cloverleaf, 59 years IT - old fart.

[Author]

Replies