- This topic has 6 replies, 3 voices, and was last updated 15 years, 5 months ago by .
-
Topic
-
I am having an issue with not getting acks back from a vendor or the believes it is not receiving a valid ack. After turning up the engine noise I noticed something in the ack message. Here a snippet of the log showing the outbound msg and inbound ack message in hex: Code:
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] writing out 578 bytes:
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 0b 4d 53 48 3a 3b 7e 5c |.MSH:;~|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 26 3a 53 50 43 3a 4e 3a |&:SPC:N:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 49 4d 3a 4e 3a 32 30 30 |IM:N:200|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 39 30 34 32 39 30 31 30 |90429010|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 3a 34 31 3a 41 44 54 |0:41:ADT|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 41 30 33 3a 39 38 33 |;A03:983|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 37 38 34 31 3a 44 3a 32 |7841:D:2|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 2e 32 3a 39 38 33 37 38 |.2:98378|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 34 31 3a 3a 41 4c 3a 3a |41::AL::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 0d 45 56 4e 3a 41 30 33 |.EVN:A03|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 32 30 30 39 30 34 32 |:2009042|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 39 30 31 30 30 3a 3a 0d |90100::.|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 50 49 44 3a 3a 30 30 39 |PID::009|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 34 39 39 30 3a 31 30 |14990:10|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 32 39 32 33 36 3b 3b 3b |29236;;;|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 4e 3a 31 30 32 39 34 30 |N:102940|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 4e 31 39 35 34 34 30 |;N195440|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 54 45 53 54 3b 41 4e |:TEST;AN|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 44 52 45 41 3b 4c 3b 3a |DREA;L;:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 31 39 38 30 30 35 32 |:1980052|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 3a 46 3a 3a 31 3a 33 |0:F::1:3|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 31 20 48 4f 53 50 49 |01 HOSPI|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 54 41 4c 20 44 52 3b 3b |TAL DR;;|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 47 4c 45 4e 20 42 55 52 |GLEN BUR|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 4e 49 45 3b 4d 44 3b 32 |NIE;MD;2|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 30 36 31 3b 55 53 3b |1061;US;|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 43 3b 30 32 3a 30 32 3a |C;02:02:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 28 34 31 30 29 37 38 37 |(410)787|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 2d 34 34 34 34 3a 28 34 |-4444:(4|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 30 29 37 38 37 2d 34 |10)787-4|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 30 30 3a 45 4e 47 4c |000:ENGL|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 49 53 48 3b 45 3b 3a 4d |ISH;E;:M|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3b 3a 39 31 31 37 30 |:;:91170|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 30 30 32 3b 3b 3b 4e |0002;;;N|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 39 39 39 2d 39 39 2d |:999-99-|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 39 39 39 39 3a 0d 50 44 |9999:.PD|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 3a 3a 3a 3a 3b 44 49 |1::::;DI|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 58 3b 3b 3a 3a 3a 3a 3a |X;;:::::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 4e 3a 0d 4e 4b |:::N:.NK|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 3a 31 3a 54 45 53 54 |1:1:TEST|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 4a 55 41 4e 3a 48 3b |;JUAN:H;|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 3a 33 30 31 20 48 4f |;:301 HO|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 53 50 49 54 41 4c 20 44 |SPITAL D|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 52 3b 3b 47 4c 45 4e 20 |R;;GLEN |
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 42 55 52 4e 49 45 3b 4d |BURNIE;M|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 44 3b 32 31 30 36 31 3b |D;21061;|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 55 53 3a 28 34 31 30 29 |US:(410)|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 37 38 37 2d 34 34 34 34 |787-4444|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 0d 50 56 31 3a 3a 45 3a |.PV1::E:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 3b 3b 4e 3b 3b 3b 3a |;;;N;;;:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 39 39 39 3b 50 |:::999;P|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 48 59 53 20 45 4d 45 52 |HYS EMER|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 20 53 45 52 56 3b 44 4f | SERV;DO|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 43 54 4f 52 3a 3a 22 22 |CTOR::””|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 4d 45 44 3a 3a 3a 3a |:MED::::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 39 39 39 3b 50 |:::999;P|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 48 59 53 20 45 4d 45 52 |HYS EMER|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 20 53 45 52 56 3b 44 4f | SERV;DO|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 43 54 4f 52 3a 4f 45 52 |CTOR:OER|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 3b 4e 3a 30 39 31 31 |;;N:0911|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 37 30 30 30 30 32 3b 3b |700002;;|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3b 4e 3a 53 3a 3a 3a 3a |;N:S::::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 3a 3a 3a 3a 3a |::::::::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 3a 33 31 3a 3a |::::31::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 4e 3a 3a 3a 3a 3a 32 |:N:::::2|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 30 39 30 34 32 37 31 |00904271|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 32 31 3a 32 30 30 39 |121:2009|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 30 34 32 37 32 33 35 39 |04272359|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 3a 0d 5a 43 41 |::::.ZCA|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 3a 3a 3b 3b 3b 0d 5a |:::;;;.Z|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 43 56 3a 3a 3a 3a 3a 3a |CV::::::|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 3a 4f 45 52 3a 31 0d 0d |:OER:1..|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 1c 0d |..|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] write buffer has 578 bytes, currently at +0
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] wrote 578 bytes out of 578
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] write buffer has 578 bytes, currently at +578
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] Calling Tcl procedure: write.done
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] with args: {{status ok}}
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] Tcl procedure write.done returns ”
[pdl :PDL :DBUG/2:umms_ensemble:05/07/2009 13:45:32] PDL changed states: old 2, new 0
[pdl :wrte:DBUG/1:umms_ensemble:05/07/2009 13:45:32] PDL did write msg: code = 0
[pd :pdtd:INFO/1:umms_ensemble:05/07/2009 13:45:32] [0.0.34466145] Writing message succeeded
[pd :pdtd:INFO/0:umms_ensemble:05/07/2009 13:45:32] NOW AWAITING A REPLY!
[diag:leak:DBUG/0:umms_ensemble:05/07/2009 13:45:32] diag ev alloc 0x262e3548
[diag:leak:DBUG/0:umms_ensemble:05/07/2009 13:45:32] diag dqe alloc 0x22630708
[pti :even:DBUG/0:umms_ensemble:05/07/2009 13:45:32] Registering TIMER () event 0x262e3548 for tid 19
[pti :even:DBUG/0:umms_ensemble:05/07/2009 13:45:32] Registering TIMER event for tid 19
[dbi :elog:DBUG/3:umms_ensemble:05/07/2009 13:45:32] [0.0.35170939] Looking for mid in error db
[dbi :rlog:DBUG/3:umms_ensemble:05/07/2009 13:45:32] [0.0.35170939] Looking for mid in recovery db
[msg :Mid :DBUG/3:umms_ensemble:05/07/2009 13:45:32] Assigned mid [0.0.35170939] to msg 30099b28
[msg :Msg :DBUG/0:umms_ensemble:05/07/2009 13:45:32] [0.0.35170939] MSG alloc 0x30099b28
[msg :Mid :DBUG/3:umms_ensemble:05/07/2009 13:45:32] msgCopy from 0x3008ca28 [0.0.34466145]
[msg :Mid :DBUG/3:umms_ensemble:05/07/2009 13:45:32] msgCopy to 0x30099b28 [0.0.35170939]
[pd :pdtd:INFO/1:umms_ensemble:05/07/2009 13:45:32] [0.0.34466145] Latencies: Outbound 737080.857, Que 1891.420, Total 0.006 secs
[dbi :rlog:INFO/1:umms_ensemble:05/07/2009 13:45:32] [0.0.34466145] Update msg in recovery db to state OB delivered OK
[dbi :log :DBUG/2:umms_ensemble:05/07/2009 13:45:32] log context: type 1, dbn 1, msgRec 10001, mdRec 10002, bodyRec 10003
[dbi :log :DBUG/2:umms_ensemble:05/07/2009 13:45:32] state 14, mode 1
[dbi :log :DBUG/2:umms_ensemble:05/07/2009 13:45:32] update var MD, upd 1, dirty 0
[pd :pdtd:INFO/2:umms_ensemble:05/07/2009 13:45:32] [0.0.34466145] Msg not saved into outbound save file
[pd :thrd:INFO/0:umms_ensemble:05/07/2009 13:45:32] [0.0.34466145] Invoking SENDOK
[pd :pdtd:INFO/0:umms_ensemble:05/07/2009 13:45:32] [0.0.34466145] Executing send_data_ok TPS
[tps :tps :INFO/1:umms_ensemble:05/07/2009 13:45:32] tds.string = save_ob_msg_38 {MSGID message0} {CONTEXT send_data_ok} {ARGS {{DEBUG 1}}} {MODE run} {VERSION 3.0}
SAVE_OB_MSG_38/umms_ensemble/send_data_ok: Saved msg with MID ‘0.0.34466145’ to variable ob_save
[msg :Mid :DBUG/0:umms_ensemble:05/07/2009 13:45:32] mid free [0.0.34466145] 0x20f90e78
[diag:leak:DBUG/0:umms_ensemble:05/07/2009 13:45:32] diag pmd alloc 0x20f90e78
[diag:leak:DBUG/0:umms_ensemble:05/07/2009 13:45:32] diag pmd free 0x20f90e78
[pti :sche:INFO/1:umms_ensemble:05/07/2009 13:45:32] Thread has 0 ready events left.
[pd :thrd:INFO/1:umms_ensemble:05/07/2009 13:45:32] OB-Data queue has 119 msgs
[pd :thrd:INFO/1:umms_ensemble:05/07/2009 13:45:32] OB-Data queue has NO work
[pti :sche:INFO/2:umms_ensemble:05/07/2009 13:45:32] Performing apply callback for thread 19
[msi :msi :DBUG/1:umms_ensemble:05/07/2009 13:45:32] msiExportStats: export for thread: umms_ensemble
[pti :sche:DBUG/2:umms_ensemble:05/07/2009 13:45:32] Thread 19 has been enabled
[pti :sche:INFO/1:umms_ensemble:05/07/2009 13:45:32] Thread has 1 ready events.
[pti :even:DBUG/0:umms_ensemble:05/07/2009 13:45:32] Processing SOCKET (PDL server) event 0x275579d8
[pti :even:DBUG/1:umms_ensemble:05/07/2009 13:45:32] Calling cb 0x200b1c3c
[pdl :read:DBUG/2:umms_ensemble:05/07/2009 13:45:32] Events: E 0, R 8, W 0
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] read 92 bytes
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] input buffer accepted 92 bytes, now 92
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 0b 4d 53 48 3a 3b 7e 5c |.MSH:;~|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 26 3a 45 6e 73 65 6d 62 |&:Ensemb|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 6c 65 48 4c 37 3a 49 53 |leHL7:IS|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 43 3a 53 50 43 3a 4e 3a |C:SPC:N:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 32 30 30 39 30 35 30 37 |20090507|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 31 33 34 35 3a 3a 41 43 |1345::AC|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 4b 3b 41 30 33 3a 39 38 |K;A03:98|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 33 37 38 34 31 3a 44 3a |37841:D:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 32 2e 32 3a 39 38 33 37 |2.2:9837|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 38 34 31 0d 4d 53 41 3a |841.MSA:|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 41 41 3a 39 38 33 37 38 |AA:98378|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] 34 31 0d 0d |41..|
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] IDLE and 92 bytes but no error: starting READ
[pdl :PDL :DBUG/2:umms_ensemble:05/07/2009 13:45:32] PDL changed states: old 0, new 1
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] Calling Tcl procedure: hci_pd.read
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] with args: {}
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] Tcl procedure hci_pd.read returns ‘RECEIVE’
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] trying to match phrase: basic-msg
[pdl :PDL :DBUG/1:umms_ensemble:05/07/2009 13:45:32] PDL setting timeout in 15.00 seconds
[diag:leak:DBUG/0:umms_ensemble:05/07/2009 13:45:32] diag ev alloc 0x275513c8
[diag:leak:DBUG/0:umms_ensemble:05/07/2009 13:45:32] diag dqe alloc 0x254c0f38
[pti :even:DBUG/0:umms_ensemble:05/07/2009 13:45:32] Registering TIMER () event 0x275513c8 for tid 19
[pti :even:DBUG/0:umms_ensemble:05/07/2009 13:45:32] Registering TIMER event for tid 19
[pdl :PDL :DBUG/0:umms_ensemble:05/07/2009 13:45:32] READ operation in progress (92 bytes buffered still, 92 before)
[pti :sche:INFO/1:umms_ensemble:05/07/2009 13:45:32] Thread has 0 ready events left.
[pd :thrd:INFO/1:umms_ensemble:05/07/2009 13:45:32] OB-Data queue has 119 msgs
[pd :thrd:INFO/1:umms_ensemble:05/07/2009 13:45:32] OB-Data queue has NO work
[pti :sche:INFO/2:umms_ensemble:05/07/2009 13:45:32] Performing apply callback for thread 19
[msi :msi :DBUG/1:umms_ensemble:05/07/2009 13:45:32] msiExportStats: export for thread: umms_ensemble
What I noticed is the ack message is terminated by 0d 0d, instead of 1c 0d. Is correct for me to tell the vendor their ack message encapsulation characters are incorrect and this why the engine believes it is not receiving a valid ack?
- The forum ‘Cloverleaf’ is closed to new topics and replies.