Not processing ACK

I have an issue with an interface that was working until the vendor performed an upgrade. Now, the interface awaits a reply indefinately, attempting to resend the message forever, even though the receiving system is sending ACKs. When I unchecked Await Replies, I started seeing the following message in the logs:

[pdl :PDL :ERR /0: t_optiflex_a:07/26/2013 06:49:38] no-match: no more phrases to try

I’m going to guess that this was happening because the ACK was coming in unexpectedly.

When I turned ‘Awaiting Replies’ back on, and configured Reply Generation, Inbound TPS Reply, and Send OK procs, it sits there.

I turned up logging and saw the following in the logs:

[pd  :pdtd:INFO/0: t_optiflex_a:07/26/2013 08:50:28] NOW AWAITING A REPLY!

[diag:leak:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] diag ev alloc 0x25ae3bc8

[diag:leak:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] diag dqe alloc 0x25a79628

[pti :even:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Registering TIMER () event 0x25ae3bc8 for tid 11

[pti :even:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Registering TIMER event for tid 11

[dbi :elog:DBUG/3: t_optiflex_a:07/26/2013 08:50:28] [0.0.214366158] Looking for mid in error db

[dbi :rlog:DBUG/3: t_optiflex_a:07/26/2013 08:50:28] [0.0.214366158] Looking for mid in recovery db

[msg :Mid :DBUG/3: t_optiflex_a:07/26/2013 08:50:28] Assigned mid [0.0.214366158] to msg 30045b28

[msg :Msg :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] [0.0.214366158] MSG alloc 0x30045b28

[msg :Mid :DBUG/3: t_optiflex_a:07/26/2013 08:50:28] msgCopy from 0x30125928 [0.0.214365212]

[msg :Mid :DBUG/3: t_optiflex_a:07/26/2013 08:50:28] msgCopy to   0x30045b28 [0.0.214366158]

[pd  :pdtd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] [0.0.214365212] Latencies: Outbound 294.580, Que 0.436, Total 294.708 secs

[dbi :rlog:INFO/1: t_optiflex_a:07/26/2013 08:50:28] [0.0.214365212] Update msg in recovery db to state OB delivered OK

[dbi :log :DBUG/2: t_optiflex_a:07/26/2013 08:50:28] log context: type 1, dbn 1, msgRec 10001, mdRec 10002, bodyRec 10003

[dbi :log :DBUG/2: t_optiflex_a:07/26/2013 08:50:28]              state 14, mode 1

[dbi :log :DBUG/2: t_optiflex_a:07/26/2013 08:50:28] update var MD, upd 1, dirty 0

[pd  :pdtd:INFO/2: t_optiflex_a:07/26/2013 08:50:28] [0.0.214365212] Writing msg to outbound save file t_optiflex_a

[pd  :pdtd:INFO/2: t_optiflex_a:07/26/2013 08:50:28] Opening “t_optiflex_a” as outbound save msg file

[pd  :thrd:INFO/0: t_optiflex_a:07/26/2013 08:50:28] [0.0.214365212] Invoking SENDOK

[pd  :pdtd:INFO/0: t_optiflex_a:07/26/2013 08:50:28] [0.0.214365212] Executing send_data_ok TPS

[tps :tps :INFO/1: t_optiflex_a:07/26/2013 08:50:28] tds.string = sendOK_save {MSGID message0} {CONTEXT send_data_ok} {ARGS {}} {MODE run} {VERSION 3.0}

[msg :Mid :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] mid free [0.0.214365212] 0x20df1658

[diag:leak:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] diag pmd alloc 0x20df1658

[diag:leak:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] diag pmd free  0x20df1658

[pti :sche:INFO/1: t_optiflex_a:07/26/2013 08:50:28] Thread has 0 ready events left.

[pd  :thrd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] OB-Data queue has 12 msgs

[pd  :thrd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] OB-Data queue has NO work

[pti :sche:INFO/2: t_optiflex_a:07/26/2013 08:50:28] Performing apply callback for thread 11

[msi :msi :DBUG/1: t_optiflex_a:07/26/2013 08:50:28] msiExportStats: export for thread: t_optiflex_a

[cmd :cmd :INFO/0:      adt_cmd:07/26/2013 08:50:28] Receiving a command

[cmd :cmd :INFO/0:      adt_cmd:07/26/2013 08:50:28] Command client went away.  Closing connection.

[pd  :thrd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] OB-Data queue has 12 msgs

[pd  :thrd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] OB-Data queue has NO work

[pti :sche:INFO/2: t_optiflex_a:07/26/2013 08:50:28] Performing apply callback for thread 11

[msi :msi :DBUG/1: t_optiflex_a:07/26/2013 08:50:28] msiExportStats: export for thread: t_optiflex_a

[pd  :thrd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] OB-Data queue has 12 msgs

[pd  :thrd:INFO/1: t_optiflex_a:07/26/2013 08:50:28] OB-Data queue has NO work

[pti :sche:INFO/2: t_optiflex_a:07/26/2013 08:50:28] Performing apply callback for thread 11

[msi :msi :DBUG/1: t_optiflex_a:07/26/2013 08:50:28] msiExportStats: export for thread: t_optiflex_a

[pti :sche:DBUG/2: t_optiflex_a:07/26/2013 08:50:28] Thread 11 has been enabled

[pti :sche:INFO/1: t_optiflex_a:07/26/2013 08:50:28] Thread has 1 ready events.

[pti :even:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Processing SOCKET (PDL server) event 0x25f38ca8

[pti :even:DBUG/1: t_optiflex_a:07/26/2013 08:50:28] Calling cb 0x200b1c3c

[pdl :read:DBUG/2: t_optiflex_a:07/26/2013 08:50:28] Events: E 0, R 8, W 0

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] read 88 bytes

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] input buffer accepted 88 bytes, now 88

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  0b 4d 53 48  7c 5e 7e 5c  |.MSH|^~|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  26 7c 4f 50  54 49 46 4c  |&|OPTIFL|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  45 58 7c 53  4d 48 7c 53  |EX|SMH|S|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  4d 48 41 44  54 7c 53 4d  |MHADT|SM|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  48 7c 32 30  31 33 30 37  |H|201307|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  32 36 30 38  35 30 32 38  |26085028|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  7c 7c 41 43  4b 7c 30 30  |||ACK|00|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  33 31 33 37  32 31 31 7c  |3137211||

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  50 7c 32 2e  33 0d 4d 53  |P|2.3.MS|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  41 7c 41 41  7c 30 30 33  |A|AA|003|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28]  31 33 37 32  31 31 0d 1c  |137211..|

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] IDLE and 88 bytes but no error: starting READ

[pdl :PDL :DBUG/2: t_optiflex_a:07/26/2013 08:50:28] PDL changed states: old 0, new 1

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Calling Tcl procedure: hci_pd.read

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] with args: {}

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Tcl procedure hci_pd.read returns ‘RECEIVE’

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] trying to match phrase: basic-msg

[pdl :PDL :DBUG/1: t_optiflex_a:07/26/2013 08:50:28] PDL setting timeout in 15.00 seconds

[diag:leak:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] diag ev alloc 0x25f80ce8

[diag:leak:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] diag dqe alloc 0x20c91788

[pti :even:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Registering TIMER () event 0x25f80ce8 for tid 11

[pti :even:DBUG/0: t_optiflex_a:07/26/2013 08:50:28] Registering TIMER event for tid 11

[pdl :PDL :DBUG/0: t_optiflex_a:07/26/2013 08:50:28] READ operation in progress (88 bytes buffered still, 88 before)

[pti :sche:INFO/1: t_optiflex_a:07/26/2013 08:50:28] Thread has 0 ready events left.

I see where the ACK comes back in, but I don’t see anything done with it. MSH-10 contains the same message control ID as the outbound message, and everything looks OK to me, though I don’t have a wealth of experience with acknowledgment processing. Everything has just ‘worked’ with the standard configuration, to this point.

Can anyone see why the ACK would not be processed? For now I have Await Replies disabled.