Error 201 (Tcl failure in IB data TPS)

Jim,

The log file for this process shows this:

03/01/2007 12:59:58

[pdl :PDL :ERR /0:lpc_professional_chg_out] no-match: no more phrases to try

(validate_hl7ack/lpc_professional_chg_out) : Received Invalid response

Message to Error Database

Message is:

Reply is:

^KMSH|^~&|HNAM|HNAM|HNAM|L|20061128140024||ACK|Q357651490T490397787||2.3^MMSA|AA|Q357651490T490397787|

I see this many times in the log file (for a period of time).  It looks like it is there for every message that is sent to the receiving system.

Further in the log file I see this.  I don’t know if it has anything to do with the error above.  I do know the person on the receiving system has been trying different things on his side, so, he has been turning this interface off and on on his side.

03/01/2007 14:36:00

[icl :tcpi:ERR /0: olltest2_cmd] write failed: Broken pipe

[cmd :cmd :INFO/0: olltest2_cmd] Since there are some error had occured while attempted to send an Ack back to client

[cmd :cmd :INFO/0: olltest2_cmd] We try to process the command anyway but no further Ack will be send back to Client

[cmd :cmd :INFO/0: olltest2_cmd] Received command: ‘lpc_professional_chg_out pstop’

03/01/2007 14:36:00

[cmd :cmd :WARN/0: olltest2_cmd] Thread is not running ‘lpc_professional_chg_out’

[cmd :cmd :INFO/0: olltest2_cmd] Inrecoverable socket error.  Closing connection.

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

03/01/2007 14:36:00

[icl :tcpi:ERR /0: olltest2_cmd] write failed: Broken pipe

[cmd :cmd :INFO/0: olltest2_cmd] Since there are some error had occured while attempted to send an Ack back to client

[cmd :cmd :INFO/0: olltest2_cmd] We try to process the command anyway but no further Ack will be send back to Client

[cmd :cmd :INFO/0: olltest2_cmd] Received command: ‘lpc_professional_chg_out pstop’

03/01/2007 14:36:00

[cmd :cmd :WARN/0: olltest2_cmd] Thread is not running ‘lpc_professional_chg_out’

[cmd :cmd :INFO/0: olltest2_cmd] Inrecoverable socket error.  Closing connection.

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

OK, Jim.

I will do this.  

You are telling me to turn on the enable_all for this outbound thread, correct?

Ariba

Can I just leave this on overnight?

Jim,

This is what I see with enable_all turned on.  I have no idea what all of this means.

[msg :Msg :INFO/0:lpc_professional_chg_out] [0.0.1087225] Writing to recovery database

[dbi :rlog:INFO/1:lpc_professional_chg_out] [0.0.1087225] Write msg to recovery db w/state IB pre-SMS

[dbi :log :DBUG/2:lpc_professional_chg_out] log context: type 1, dbn 1, msgRec 10001, mdRec 10002, bodyRec 10003

[dbi :log :DBUG/2:lpc_professional_chg_out]              state 1, mode 0

[dbi :log :DBUG/2:lpc_professional_chg_out] update var MD, upd 0, dirty 1

[dbi :log :DBUG/1:lpc_professional_chg_out] metaData: dest 24(-1), origDest 24(-1), drvCtl 0(-1),

         userData 0(-1), recFmt 0(-1), sepChars 0(-1)

[dbi :log :DBUG/1:lpc_professional_chg_out] msgWriteTraverse: len 146, off 0, rem 1000, alloc 0

[dbi :log :DBUG/2:lpc_professional_chg_out]     while: len 146, doff 0, off 0, rem 1000, upd 0

[dbi :log :DBUG/2:lpc_professional_chg_out]        fillnew

[dbi :log :DBUG/1:lpc_professional_chg_out] msgWriteTraverse: len 0, off 146, rem 854, alloc 0

[pdl :PDL :DBUG/0:lpc_professional_chg_out] READ operation completed (28 bytes buffered still, 177 before)

[pdl :PDL :DBUG/0:lpc_professional_chg_out] IDLE and 28 bytes but no error: starting READ

[pdl :PDL :DBUG/2:lpc_professional_chg_out] PDL changed states: old 0, new 1

[pdl :PDL :DBUG/0:lpc_professional_chg_out] Calling Tcl procedure: hci_pd.read

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

[pdl :PDL :DBUG/0:lpc_professional_chg_out] Tcl procedure hci_pd.read returns ‘RECEIVE’

[pdl :PDL :DBUG/0:lpc_professional_chg_out] trying to match phrase: basic-msg

[pdl :PDL :DBUG/0:lpc_professional_chg_out] multi: phrase #0 rejected; trying next

03/01/2007 16:17:13

[pdl :PDL :ERR /0:lpc_professional_chg_out] no-match: no more phrases to try

[pdl :PDL :DBUG/0:lpc_professional_chg_out] Calling Tcl procedure: read.error

[pdl :PDL :DBUG/0:lpc_professional_chg_out] with args: {{status error} {type no-match}}

[pdl :PDL :DBUG/0:lpc_professional_chg_out] pdiIgnoreInput: chop to 1, bolen 0

[pdl :PDL :DBUG/0:lpc_professional_chg_out] pdiIgnoreInput: after memmove: 0 + 27

[pdl :PDL :DBUG/0:lpc_professional_chg_out] pdiIgnoreInput: chop to 4294967295, bolen 0

[pdl :PDL :DBUG/0:lpc_professional_chg_out] pdiIgnoreInput: after clear: 0 + 0

[pdl :PDL :DBUG/0:lpc_professional_chg_out] Tcl procedure read.error returns ‘0’

[pdl :PDL :DBUG/2:lpc_professional_chg_out] PDL changed states: old 1, new 0

[pdl :PDL :DBUG/0:lpc_professional_chg_out] READ operation completed (0 bytes buffered still, 28 before)

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

[pd  :thrd:INFO/1:lpc_professional_chg_out] IB-Pre-SMS queue has 1 msgs

[pti :sche:DBUG/2:lpc_professional_chg_out] Thread 11 has been enabled

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

[pti :even:DBUG/0:lpc_professional_chg_out] Processing POLLED () event 0x22746308

[pti :even:DBUG/1:lpc_professional_chg_out] Calling cb 0x2009a810

[pd  :thrd:INFO/1:lpc_professional_chg_out] IB-Pre-SMS queue has 1 msgs

[pd  :thrd:INFO/0:lpc_professional_chg_out] Processing IB-Pre-SMS message queue

[sms :sms :INFO/0:lpc_professional_chg_out] [0.0.1087225] SMS Received msg

[sms :sms :INFO/0:lpc_professional_chg_out] [0.0.1087225] Driver processing msg

[tps :tps :INFO/1:lpc_professional_chg_out] tds.string = validate_hl7ack {MSGID message1} {CONTEXT sms_ib_reply} {ARGS {}} {MODE run} {VERSION 3.0}

(validate_hl7ack/lpc_professional_chg_out) : Received Invalid response

Message to Error Database

Message is:

Reply is:

MSH|^~&|HNAM|HNAM|HNAM|L|20061128170028||ACK|Q357651783T490398099|P|2.3|Q357651783T490398099|||

MSA|AA|Q357651783T490398099|Record Processed||||

[sms :sms :INFO/1:lpc_professional_chg_out] Handling disposition ‘KILLREPLY’ for ‘message1’

[dbi :rlog:INFO/0:lpc_professional_chg_out] [0.0.1087225] Delete message from recovery database

[msg :Msg :DBUG/0:lpc_professional_chg_out] [0.0.1087225] msgFree 0x3007e828

[pd  :pdtd:DBUG/0:lpc_professional_chg_out] Shutting down await reply mode

[msg :Msg :DBUG/0:lpc_professional_chg_out] [0.0.1087226] msgFree 0x3007e03c

[pti :even:DBUG/0:lpc_professional_chg_out] Unregistering TIMER () event 0x2288e8b8 for tid 11

[pti :even:DBUG/0:lpc_professional_chg_out] evUnregister TIMER event 0x2288E8B8 for tid 11

[diag:leak:DBUG/0:lpc_professional_chg_out] diag dqe free  0x22746528

[diag:leak:DBUG/0:lpc_professional_chg_out] diag ev free  0x2288e8b8

[msg :Mid :DBUG/0:lpc_professional_chg_out] mid free [0.0.1087225] 0x20de1e48

[dbi :rlog:INFO/0:lpc_professional_chg_out] [0.0.1087178] Transitioning msg to error db w/state 201

[dbi :rlog:INFO/1:lpc_professional_chg_out] [0.0.1087178] Update msg in recovery db to state Tcl failure in IB data TPS

[dbi :log :DBUG/2:lpc_professional_chg_out] log context: type 1, dbn 1, msgRec 10001, mdRec 10002, bodyRec 10003

[dbi :log :DBUG/2:lpc_professional_chg_out]              state 201, mode 1

[dbi :log :DBUG/2:lpc_professional_chg_out] update var MD, upd 1, dirty 1

[dbi :log :DBUG/1:lpc_professional_chg_out] metaData: dest 0(-1), origDest 0(-1), drvCtl 0(-1),

         userData 165(-1), recFmt 0(-1), sepChars 0(-1)

[dbi :log :DBUG/1:lpc_professional_chg_out] writeMetaData: len 0, off -1, upd 1, l 1

[dbi :elog:INFO/0:lpc_professional_chg_out] [0.0.1087178] Write message to error database, state 201

[dbi :log :DBUG/2:lpc_professional_chg_out] log context: type 2, dbn 2, msgRec 10000, mdRec 10001, bodyRec 10002

[dbi :log :DBUG/2:lpc_professional_chg_out]              state 201, mode 0

[dbi :log :DBUG/2:lpc_professional_chg_out] update var MD, upd 0, dirty 0

[dbi :log :DBUG/1:lpc_professional_chg_out] metaData: dest 0(-1), origDest 0(-1), drvCtl 0(-1),

         userData 165(-1), recFmt 0(-1), sepChars 0(-1)

[dbi :log :DBUG/1:lpc_professional_chg_out] msgWriteTraverse: len 176, off 0, rem 1000, alloc 0

[dbi :log :DBUG/2:lpc_professional_chg_out]     while: len 176, doff 0, off 0, rem 1000, upd 0

[dbi :log :DBUG/1:lpc_professional_chg_out] msgWriteTraverse: len 1180, off 176, rem 824, alloc 0

[dbi :log :DBUG/2:lpc_professional_chg_out]     while: len 1180, doff 0, off 176, rem 824, upd 0

[dbi :log :DBUG/2:lpc_professional_chg_out]        fillnew

[dbi :log :DBUG/2:lpc_professional_chg_out]     while: len 356, doff 824, off 0, rem 1000, upd 0

[dbi :log :DBUG/2:lpc_professional_chg_out]        fillnew

[dbi :log :DBUG/1:lpc_professional_chg_out] msgWriteTraverse: len 0, off 356, rem 644, alloc 0

[dbi :elog:INFO/0:lpc_professional_chg_out] [0.0.1087178] Setting error context for message

[dbi :elog:INFO/1:lpc_professional_chg_out] [0.0.1087178] Context: TPS ERROR disposition

[dbi :rlog:INFO/0:lpc_professional_chg_out] [0.0.1087178] Delete message from recovery database

[msg :Msg :DBUG/0:lpc_professional_chg_out] [0.0.1087178] msgFree 0x3006c528

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

[pti :sche:INFO/2:lpc_professional_chg_out] Performing apply callback for thread 11

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

Engine idle — 03/01/2007 16:17:23

OK.  I hadn’t read your response, Jim.  I will do like Kevin said and see if I get the hex dump info.

I’ll let you know what I see.

Thanks,

Ariba

I do not have an enable_pdl in my list.

When I go to Control, Full, EO config, EO Alias, I only see the following choices:

binary_message_only

disable_all

enable_all

enable_all_info

enable_all_info_1

enable_all_info_2

enable_all_info_3

message_details

meta_message_only

BTW- This is in my test environment. This is something we are trying to get working before it goes to live.

We are on version 5.2.1P

Thanks,

Ariba

OK, Jim.  I will try this.

I just looked at the process log file for this thread and this is what I see.  I haven’t done what you suggested yet. I just went to check the log file because I could see that messages had stopped flowing to the receiving system for this interface.  

Is this helpful in any way??

03/02/2007 11:00:49

[pdl :PDL :ERR /0:lpc_outreach_chg_out] no-match: no more phrases to try

(validate_hl7ack/lpc_outreach_chg_out) : Received Invalid response

Message to Error Database

Message is:

03/02/2007 11:00:49

[sms :sms :ERR /0:lpc_outreach_chg_out] Tcl error:

       msgId   = message0

       proc    = ‘validate_hl7ack’

       args    = ”

       result  = ‘bad msgId “”‘

       errorInfo: ‘

bad msgId “”

   while executing

“msgget $my_mh”

   (“default” arm line 6)

   invoked from within

“switch -exact — $acktype {

               AA – CA {

                       # Good ACK – Clean up

                       set send_cnt 0 ;# Init co…”

   (“run” arm line 18)

   invoked from within

“switch -exact — $mode {

       start {

           if ![info exists ob_save] {set ob_save “”}

         set send_cnt 0        ;# Init counter

     …”

   (procedure “validate_hl7ack” line 12)

   invoked from within

“validate_hl7ack {MSGID message0} {CONTEXT sms_ib_reply} {ARGS {}} {MODE run} {VERSION 3.0}”‘

*************************************************************

I’ll let you know what I see when I do what you suggested.

Thanks,

Ariba

Here is what I see with enable_all turned on for this thread.

This is the acknowlegement the receiving system is sending back to Cloverleaf.

pti :even:DBUG/1:lpc_outreach_chg_out] Calling cb 0x20099328

[pdl :read:DBUG/2:lpc_outreach_chg_out] Events: E 0, R 8, W 0

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] read 177 bytes

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] input buffer accepted 177 bytes, now 177

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  0b 0b 4d 53  48 7c 5e 7e  |..MSH|^~|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  5c 26 7c 48  4e 41 4d 7c  |&|HNAM||

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  48 4e 41 4d  7c 48 4e 41  |HNAM|HNA|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  4d 7c 4c 7c  32 30 30 37  |M|L|2007|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  30 33 30 32  31 31 30 37  |03021107|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  33 30 7c 7c  41 43 4b 7c  |30||ACK||

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  51 34 30 31  30 37 30 32  |Q4010702|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  33 31 54 35  34 34 38 31  |31T54481|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  39 36 33 35  7c 50 7c 32  |9635|P|2|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  2e 33 7c 51  34 30 31 30  |.3|Q4010|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  37 30 32 33  31 54 35 34  |70231T54|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  34 38 31 39  36 33 35 7c  |4819635||

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  7c 7c 0d 4d  53 41 7c 41  |||.MSA|A|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  41 7c 51 34  30 31 30 37  |A|Q40107|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  30 32 33 31  54 35 34 34  |0231T544|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  38 31 39 36  33 35 7c 52  |819635|R|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  65 63 6f 72  64 20 50 72  |ecord Pr|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  6f 63 65 73  73 65 64 7c  |ocessed||

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  7c 7c 7c 1c  0d 4d 53 41  ||||..MSA|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  7c 41 41 7c  51 34 30 31  ||AA|Q401|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  30 37 30 32  33 31 54 35  |070231T5|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  34 34 38 31  39 36 33 35  |44819635|

[pdl :PDL :DBUG/0:lpc_outreach_chg_out]  7c                        |||

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] IDLE and 177 bytes but no error: starting READ

[pdl :PDL :DBUG/2:lpc_outreach_chg_out] PDL changed states: old 0, new 1

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] Calling Tcl procedure: hci_pd.read

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

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] Tcl procedure hci_pd.read returns ‘RECEIVE’

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] trying to match phrase: basic-msg

[pdl :PDL :DBUG/0:lpc_outreach_chg_out] multi_phrase_2: status = ok

Should there be the two 0b values at the beginning of this message?  I immediately noticed that.

Thanks,

Ariba

OK.  I have done that.  The receiving system seems to see where they are putting in the two 0b values at the beginning of the message. I think the programmer has even identified the fact that the ending portion of his acknowledgement is not correct.

We will test again after he makes changes.

Thanks,

Ariba

Jim,

The receiving system has made a change to possibly fix the issue with their acknowledgement.  We are trying to test this again.

When I turn on the enable_all for the outbound thread that sends the messages to the receiving system, I just see

Loading…………………………………………………………………………..

………………………………………………….

Any idea why I can ‘t see any output here?  There are messages waiting to be sent through this interface.

thanks,

Ariba

To turn off enable_all, I just do a disable_all, right?

That is what I did.  It’s the only way I know to turn this off.

Thanks,

Ariba