ACKs written to Recovery database

[Peter Heggie]

I must have the just the wrong configuration set in the outbound and outbound reply settings, because the Recovery Database is filling up with ACK (msgstate 1) messages.

This vendor closes its connection after sending each ACK, so this is not a standard outbound thread.

On the tcp/ip protocol settings, using mlp_tcp, Auto-Reconnect is On, Reopen Time is 3 seconds, Delay Connection is off, Close After Write is off, and use DRIVERCTL is off.

On the outbound settings, there is a an Outbound Data proc, and then retries is -1 and Interval is 10.

On the Inbound Replies, Await Replies is checked, the timeout is 45 and timeout handling is Resend OB Message.

The pending message count never goes down but the messages in and messages out count is going up evenly.

The ACK message seems to be formatted correctly:

Code:

[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  0b 4d 53 48  7c 5e 7e 5c  |.MSH|^~|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  26 7c 50 4d  53 7c 50 4d  |&|PMS|PM|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  53 7c 43 52  4f 55 53 45  |S|CROUSE|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  7c 43 48 41  38 4a 30 7c  ||CHA8J0||
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  32 30 31 34  31 31 31 39  |20141119|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  30 38 32 37  31 31 7c 7c  |082711|||
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  41 43 4b 7c  7c 50 7c 32  |ACK||P|2|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  2e 34 7c 7c  7c 0d 4d 53  |.4|||.MS|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  41 7c 41 41  7c 7c 0d 1c  |A|AA||..|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11]  0d                        |.|
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] IDLE and 73 bytes but no error: starting READ
[pdl :PDL :DBUG/2:to_prl_adtP03:11/19/2014 08:27:11] PDL changed states: old 0, new 1
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] Calling Tcl procedure: hci_pd.read
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] with args: {}
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] Tcl procedure hci_pd.read returns ‘RECEIVE’
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] trying to match phrase: basic-msg
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] multi_phrase_2: status = ok
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] Calling Tcl procedure: read.done
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] with args: {{status ok} {end {73 0}} {data {1 70}}}
[dbi :elog:DBUG/3:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128474345] Looking for mid in error db
[dbi :dbi :DBUG/1:to_prl_adtP03:11/19/2014 08:27:11] (0) ‘cl_keyfindlock: About to do d_keylock’
[dbi :dbi :DBUG/1:to_prl_adtP03:11/19/2014 08:27:11] (0) ‘cl_keyfindlock: About to do d_keyfind, keyval:’
[dbi :rlog:DBUG/3:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128474345] Looking for mid in recovery db
[dbi :dbi :DBUG/1:to_prl_adtP03:11/19/2014 08:27:11] (0) ‘cl_keyfindlock: About to do d_keylock’
[dbi :dbi :DBUG/1:to_prl_adtP03:11/19/2014 08:27:11] (1000) ‘cl_keyfindlock: About to do d_keyfind, keyval:’
[msg :Mid :DBUG/3:to_prl_adtP03:11/19/2014 08:27:11] Assigned mid [0.0.128474345] to msg effaf128
[msg :Msg :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] msg_Alloc new message 0xeffaf128
[pdl :PDL :DBUG/0:to_prl_adtP03:11/19/2014 08:27:11] Tcl procedure read.done returns ”
[pdl :PDL :DBUG/2:to_prl_adtP03:11/19/2014 08:27:11] PDL changed states: old 1, new 0
[pdl :read:DBUG/1:to_prl_adtP03:11/19/2014 08:27:11] PDL did read msg: code = 0
[pd  :pdtd:INFO/0:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128473709] Received msg from driver
[pd  :pdtd:INFO/2:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128473709] Writing msg to inbound save file to_prl_adtP03_ib
[pd  :thrd:INFO/0:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128473709] Placing msg on IB pre-SMS queue.
[pd  :pdtd:INFO/3:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128473709] IB pre-SMS message details
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–] msg: 0xeffaee28
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgType           : REPLY
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgClass          : PROTOCOL
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgState          : Unknown: 0 (0)
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgPriority       : 5120
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgRecoveryDbState: Log:new (2)
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgFlags          : 0x8002
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgMid            : [0.0.128473709]
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgSrcMid         : midNULL
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgSrcMidGroup    : midNULL
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgHostId         : 3697929497
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgOrigSrcThread  : to_prl_adtP03
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgOrigDestThread : xfr_ch_rslt
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgSrcThread      : to_prl_adtP03
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgDestThread     : xfr_ch_rslt
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgXlateThread    :
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgSkipXlate      : 0
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgSepChars       :
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgNumRetries     : 0
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgGroupId        : 0
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgDriverControl  :
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgRecordFormat   :
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgRoutes         :
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgUserData       :
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgStaticIsDirty  : 1
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgVariableIsDirty: 1
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgTimeStartIb    : 1416403631.612
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgTimeStartOb    : 1416403590.826
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgTimeCurQueStart: 0.000
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgTimeTotalQue   : 0.000
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgTimeRecovery   : 1416403590.826
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgEoConfig       : 0x0
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     msgData (BO)      : 0xeffaef28
[pd  :pdtd:INFO/3:to_prl_adtP03:–/–/—- –:–:–]     message           : ‘MSH|^~&|PMS|PMS|CROUSE|CHA8J0|20141119082711||ACK||P|2.4|||x0dMSA|AA||x0d’
[msg :Msg :INFO/0:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128473709] Writing to recovery database
[dbi :rlog:INFO/1:to_prl_adtP03:11/19/2014 08:27:11] [0.0.128473709] Write msg to recovery db w/state IB pre-SMS

Why is it writing the ACK to the Recovery DB?

Peter

Peter Heggie
PeterHeggie@crouse.org

Topic

[Jim Kosloskey]

Peter,

Do you have anything setup to dispose of the Reply?

email: jim.kosloskey@jim-kosloskey.com 30+ years Cloverleaf, 60 years IT – old fart.

[Peter Heggie]

I actually have two tcl procs in the TPS Inbound Reply option – the first is a two line proc that writes out a timestamp to the log with milliseconds on it including a string literal that identifies the thread (by reading it as an argument), and the other is hcitpsmsgkill.

Peter Heggie
PeterHeggie@crouse.org

[Jim Kosloskey]

Does the first proc CONTINUE the REPLY Message?

email: jim.kosloskey@jim-kosloskey.com 30+ years Cloverleaf, 60 years IT – old fart.

[Peter Heggie]

BINGO!

I forgot the first rule of upoc procs – message disposition.

That fixed it – thank you.

Peter Heggie
PeterHeggie@crouse.org

[Author]

Replies