Restarting thread for every pending msg with Inbound Replies

[Stephen Bull]

Hi,

I’ve setup a new thread with inbound replies for each outbound message. With Await Replies selected for the Inbound Replies section configuration is as follows:

Timeout is set to 900 (i.e. 15 mins);

I have a Tcl TPS proc for Reply ‘generation’;

a Tcl TPS for TPS Inbound Reply (for reply message processing) and the Trx id determination Format is Health Level Seven (hl7) version 2.3, with a custom variant ACK message requiring just an MSH and an MSA segment.

The sending facility is sending reply messages for every message they receive from our engine and my thread is accepting them ok for the first message through on thread start, but not subsequent messages.

So, the first message goes out, I receive an acknowledgment ok, and then the second message goes out. Then I appear to just be waiting for a reply and my messages all go to pending. If I stop and restart the thread, this next message goes out ok, an ack is received ok, and the next pending message goes out, but then my thread waits again. To get through my pending messages I have to stop and start the thread every time to get one message out.

Could this have anything to do with open sockets/ports on the receiving end? Perhaps one is getting closed with every message when my thread expects them to always be open?

Any help is greatly appreciated!

Thanks,

Stephen

Topic

[Jim Kosloskey]

Stephen,

Turn up the Engine Output and look in the Process Log. Check to see that you are tring to resend the second message after the timeout expires (or whatever it is that you are doing when the timeout expires).

If you see Cloverleaf(R) once again waiting for a reply, but now the timeout expires, the receiving system probably has an issue.

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

[Stephen Bull]

Hi,

So I upped logging output and here is a snippet of what I’m getting after filing 3 or so messages, with a restart of the thread to get each message sent out from the queue. (This snippet chunk comes from the end of the output when after my last restart and message send. Apologies in advance for the size of this; I hope you can make sense of it!)

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:DBUG/2:   REG_TO_INO] Thread 4 has been enabled

[pti :sche:INFO/1:   REG_TO_INO] Thread has 1 ready events.

[pti :even:DBUG/0:   REG_TO_INO] Processing ACTIVE_TIMER () event 0x009FFFB8

[pti :even:DBUG/1:   REG_TO_INO] Calling cb 0x522963

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pti :even:DBUG/0:   REG_TO_INO] Unregistering ACTIVE_TIMER () event 0x009FFFB8 for tid 4

[pti :even:DBUG/0:   REG_TO_INO] evUnregister ACTIVE_TIMER event 0x9FFFB8 for tid 4

[diag:leak:DBUG/0:   REG_TO_INO] diag timeval alloc 0x009F1810

[diag:leak:DBUG/0:   REG_TO_INO] diag dqe alloc 0x009D1450

[pti :even:DBUG/0:   REG_TO_INO] Registering ACTIVE_TIMER () event 0x009FFFB8 for tid 4

[pti :even:DBUG/0:   REG_TO_INO] Registering ACTIVE_TIMER event for tid 4

[diag:leak:DBUG/0:   REG_TO_INO] diag timeval free  0x009F1810

[pti :sche:INFO/1:   REG_TO_INO] Thread has 0 ready events left.

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:INFO/2:   REG_TO_INO] Performing apply callback for thread 4

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[cmd :cmd :INFO/0:   REG700_cmd] Receiving a command

[cmd :cmd :INFO/0:   REG700_cmd] Received command: ‘REG_TO_INO pstop’

[cmd :cmd :INFO/0:   REG700_cmd] Doing ‘pstop’ command on thread ‘REG_TO_INO’

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has 1 msgs

[pd  :thrd:INFO/1:   REG_TO_INO] OB-Data queue has NO work

[pti :sche:DBUG/2:   REG_TO_INO] Thread 4 has been enabled

[pti :sche:INFO/1:   REG_TO_INO] Thread has 1 ready events.

[pti :even:DBUG/0:   REG_TO_INO] Processing PTHREADS () event 0x00A00100

[pti :msg :DBUG/1:   REG_TO_INO] Processing pthread message queues.

[pti :msg :DBUG/0:   REG_TO_INO] Processing PTHREAD msg que 0x00A5A840

[pti :msg :DBUG/1:   REG_TO_INO] Processing pthreads message

[pti :msg :DBUG/1:   REG_TO_INO] Processing PTHREAD Control Message from tid 0

[pti :msg :DBUG/1:   REG_TO_INO] Thread 4 has been told to commit suicide

[diag:leak:DBUG/0:   REG_TO_INO] diag ptm free  0x00A4EE00

[pti :sche:INFO/1:   REG_TO_INO] Thread has 0 ready events left.

[pti :sche:INFO/0:   REG_TO_INO] PTI Sched Thread 4 has been killed

[pti :thre:DBUG/3:   REG_TO_INO] Thread after callback

[pd  :thrd:INFO/0:   REG_TO_INO] Shutting down protocol thread REG_TO_INO.

[icl :serv:DBUG/0:   REG_TO_INO] ICL Shutting down server REG_TO_INO

[icl :conn:DBUG/0:   REG_TO_INO] ICL Closing connection cache entry for REG_TO_INO

[diag:leak:DBUG/0:   REG_TO_INO] diag itd free  0x00A000D8

[dbi :icl :INFO/0:   REG_TO_INO] dbiIclDeregister: deregistered ‘REG_TO_INO’

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down ACK Control TPS

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down data prewrite TPS

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down reply prewrite TPS

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down data send OK TPS

[tps :tps :INFO/1:   REG_TO_INO] tds.string = tps_archive {CONTEXT send_data_ok} {ARGS {}} {MODE shutdown} {VERSION 3.0}

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down reply send OK TPS

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down data send fail TPS

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down reply send fail TPS

[pd  :pdtd:INFO/1:   REG_TO_INO] Shutting down reply generation TPS

[tps :tps :INFO/1:   REG_TO_INO] tds.string = uwmf_tps_ib_reply_gen {CONTEXT reply_gen} {ARGS {}} {MODE shutdown} {VERSION 3.0}

[sms :sms :INFO/0:   REG_TO_INO] SMS Shuting down the SMS module

[sms :sms :INFO/0:   REG_TO_INO] Shutdown the IB data SMS stack

[sms :sms :INFO/0:   REG_TO_INO] [midNULL] Driver processing msg

[sms :sms :INFO/0:   REG_TO_INO] Shutdown the IB reply SMS stack

[sms :sms :INFO/0:   REG_TO_INO] [midNULL] Driver processing msg

[tps :tps :INFO/1:   REG_TO_INO] tds.string = tps_archive {CONTEXT sms_ib_reply} {ARGS {}} {MODE shutdown} {VERSION 3.0}

[tps :tps :INFO/1:   REG_TO_INO] tds.string = uwmf_tps_ib_reply {CONTEXT sms_ib_reply} {ARGS {}} {MODE shutdown} {VERSION 3.0}

[sms :sms :INFO/0:   REG_TO_INO] Shutdown the OB data SMS stack

[sms :sms :INFO/0:   REG_TO_INO] [midNULL] Driver processing msg

[sms :sms :INFO/0:   REG_TO_INO] Shutdown the OB reply SMS stack

[sms :sms :INFO/0:   REG_TO_INO] [midNULL] Driver processing msg

[diag:leak:DBUG/0:   REG_TO_INO] diag tc free  0x009CFF98

[diag:leak:DBUG/0:   REG_TO_INO] diag sms free  0x009D15B0

[diag:leak:DBUG/0:   REG_TO_INO] diag tc free  0x00A01630

[diag:leak:DBUG/0:   REG_TO_INO] diag sms free  0x009BA6B8

[diag:leak:DBUG/0:   REG_TO_INO] diag tc free  0x00A07DE0

[diag:leak:DBUG/0:   REG_TO_INO] diag sms free  0x009D1670

[diag:leak:DBUG/0:   REG_TO_INO] diag tc free  0x00A07D88

[diag:leak:DBUG/0:   REG_TO_INO] diag sms free  0x009D15F0

[diag:leak:DBUG/0:   REG_TO_INO] diag std free  0x009D1650

[pd  :pdtd:INFO/0:   REG_TO_INO] Shuting down Protocol Driver pdl-tcpip

[pd  :pdtd:INFO/1:   REG_TO_INO] Set driver status to PD_STATUS_CLOSING

[pdl :PDL :DBUG/2:   REG_TO_INO] PDL changed states: old 0, new 5

[pdl :PDL :DBUG/0:   REG_TO_INO] Calling Tcl procedure: hci_pd.shutdown

[pdl :PDL :DBUG/0:   REG_TO_INO] with args: {}

[pdl :PDL :DBUG/0:   REG_TO_INO] Tcl procedure hci_pd.shutdown returns ”

[pdl :PDL :DBUG/2:   REG_TO_INO] PDL changed states: old 5, new 6

[pdl :PDL :DBUG/1:   REG_TO_INO] Clearing PDL listen event

[pti :even:DBUG/0:   REG_TO_INO] Unregistering SOCKET (PDL server) event 0x009FE438 for tid 4

[pti :even:DBUG/0:   REG_TO_INO] evUnregister SOCKET event 0x9FE438 for tid 4

[pti :even:DBUG/1:   REG_TO_INO] Closed WSAEvent 2748 on socket 592

[msg :Msg :DBUG/0:   REG_TO_INO] [0.0.292736816] msgFree 0x1AD4F2F0

[pdl :clse:DBUG/1:   REG_TO_INO] PDL did shutdown: code = 0

[pd  :pdtd:INFO/1:   REG_TO_INO] Set driver status to PD_STATUS_DOWN

[diag:leak:DBUG/0:   REG_TO_INO] diag timeval free  0x009F3A78

[diag:leak:DBUG/0:   REG_TO_INO] diag pdl free  0x009C80C8

[pd  :pdtd:INFO/1:   REG_TO_INO] Set driver status to PD_STATUS_DOWN

[diag:leak:DBUG/0:   REG_TO_INO] diag pd free  0x009DD1D8

[prod:prod:INFO/0:   REG_TO_INO] Checking for leaked handles in the General interpreter…

[diag:leak:DBUG/0:   REG_TO_INO] diag tclinterp free 0x0729B310

[prod:prod:INFO/0:   REG_TO_INO] Checking for leaked handles in the TPS interpreter…

[diag:leak:DBUG/0:   REG_TO_INO] diag tclinterp free 0x0729E910

[tii :tii :INFO/1:   REG_TO_INO] Shuting down Tcl interps

[diag:leak:DBUG/0:   REG_TO_INO] diag tii free  0x009FDAF0

[pti :even:DBUG/0:   REG_TO_INO] Unregistering ACTIVE_TIMER () event 0x009FFFB8 for tid 4

[pti :even:DBUG/0:   REG_TO_INO] evUnregister ACTIVE_TIMER event 0x9FFFB8 for tid 4

[diag:leak:DBUG/0:   REG_TO_INO] diag dqe free  0x009D1450

[diag:leak:DBUG/0:   REG_TO_INO] diag ev free  0x009FFFB8

[diag:leak:DBUG/0:   REG_TO_INO] diag timeval free  0x00A31460

[msi :msi :DBUG/1:   REG_TO_INO] msiExportStats: export for thread: REG_TO_INO

[diag:leak:DBUG/0:   REG_TO_INO] diag mtd free  0x00A00178

[diag:leak:DBUG/0:   REG_TO_INO] diag mts free 0x009D0060

[diag:leak:DBUG/0:   REG_TO_INO] diag mis free 0x009D0130

[diag:leak:DBUG/0:   REG_TO_INO] diag dtd free  0x009FE658

[msg :Msg :DBUG/0:   REG_TO_INO] [0.0.292733433] msgFree 0x1AD4ECF0

[diag:leak:DBUG/0:   REG_TO_INO] diag tc free  0x1AD25970

[pti :even:DBUG/0:   REG_TO_INO] Unregistering TIMER () event 0x009FFF50 for tid 4

[pti :even:DBUG/0:   REG_TO_INO] evUnregister TIMER event 0x9FFF50 for tid 4

[diag:leak:DBUG/0:   REG_TO_INO] diag dqe free  0x009FFEC8

[diag:leak:DBUG/0:   REG_TO_INO] diag ev free  0x009FFF50

[diag:leak:DBUG/0:   REG_TO_INO] diag md free  0x00A07CD8

[diag:leak:DBUG/0:   REG_TO_INO] diag tc free  0x009FE498

[diag:leak:DBUG/0:   REG_TO_INO] diag ptd free  0x009ED080

[icl :tcpi:DBUG/0:   REG_TO_INO] Tcpip shutting down socket 2768

[icl :tcpi:DBUG/0:   REG_TO_INO] Shutdown successful

[icl :tcpi:DBUG/0:   REG_TO_INO] Tcpip closing socket 2768

[icl :tcpi:DBUG/0:   REG_TO_INO] Close successful

[diag:leak:DBUG/0:   REG_TO_INO] diag tcpip free  0x009FE4F0

[diag:leak:DBUG/0:   REG_TO_INO] diag imh free  0x009E7998

[diag:leak:DBUG/0:   REG_TO_INO] diag ev free  0x009E78B8

[diag:leak:DBUG/0:   REG_TO_INO] diag conn free  0x00A59FB8

[diag:leak:DBUG/0:   REG_TO_INO] diag conn free  0x00A5CAA8

[pti :even:DBUG/0:   REG_TO_INO] evUnregister SOCKET event 0x9EE2A0 for tid 4

[pti :even:DBUG/1:   REG_TO_INO] Closed WSAEvent 424 on socket 2768

[pti :even:DBUG/0:   REG_TO_INO] evUnregister PTHREADS event 0xA00100 for tid 4

[pti :even:DBUG/0:   REG_TO_INO] evUnregister POLLED event 0x9D13F0 for tid 4

[diag:leak:DBUG/0:   REG_TO_INO] diag ev free  0x009EE2A0

[diag:leak:DBUG/0:   REG_TO_INO] diag ev free  0x00A00100

[diag:leak:DBUG/0:   REG_TO_INO] diag ev free  0x009D13F0

[diag:leak:DBUG/0:   REG_TO_INO] diag el free  0x009F7E48

[diag:leak:DBUG/0:   REG_TO_INO] diag el free  0x00A552E0

[diag:leak:DBUG/0:   REG_TO_INO] diag el free  0x00A5A7F8

[diag:leak:DBUG/0:   REG_TO_INO] diag ptm alloc 0x00A16838

[pti :msg :DBUG/1:   REG_TO_INO] Send PTM 0x00A16838 from 4 to 0: data 0x00000000

[pti :thre:INFO/0:   REG_TO_INO] Thread exiting with status 0

[diag:leak:DBUG/0:   REG_TO_INO] diag eoc free  0x009F7E60

[cmd :cmd :INFO/0:   REG700_cmd] Receiving a command

[cmd :cmd :INFO/0:   REG700_cmd] Command client went away.  Closing connection.

[cmd :cmd :INFO/0:   REG700_cmd] Receiving a command

[cmd :cmd :INFO/0:   REG700_cmd] Received command: ‘REG_TO_INO pstart’

[cmd :cmd :INFO/0:   REG700_cmd] Doing ‘pstart’ command on ‘REG_TO_INO’

[prod:prod:INFO/0:   REG_TO_INO] Applying EO config: ”

[cmd :cmd :INFO/0:   REG700_cmd] Receiving a command

[cmd :cmd :INFO/0:   REG700_cmd] Command client went away.  Closing connection.

[Jim Kosloskey]

Stephen,

You really need the log output with the messages that were delivered including the last one and som log entries after that.

Looking at what happened after you got the logjam cleared really won’t help much.

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

[Author]

Replies