ack message encapsulation characters

This topic has 6 replies, 3 voices, and was last updated 15 years, 7 months ago by Gary Atkinson.

Creator

Topic
May 7, 2009 at 6:26 pm #50855
Gary Atkinson
Participant
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?
Creator

Topic

Viewing 5 reply threads

Author

Replies
- May 7, 2009 at 7:43 pm #67788
  Jim Kosloskey
  Participant
  Gary,
  
  You are correct that the Acknowledgment does not end with the standard 1c 0d.
  
  Send them the portion of the log that shows the hex dump of the acknoweldgment and refer them to the HL/7 MLLP standard.
  
  Hopefully that is all they will need but you could tell them what they should have (as an example show them the hex dump of the message you sent that caused the acknowledgment).
  
  email: jim.kosloskey@jim-kosloskey.com 29+ years Cloverleaf, 59 years IT - old fart.
- May 7, 2009 at 7:47 pm #67789
  Gary Atkinson
  Participant
  thanks, Jim. As usual I need to prove it is not “me” causing the issue 🙄
- May 7, 2009 at 8:04 pm #67790
  James Cobane
  Participant
  As usual, the interface engine is “Guilty, until proven innocent”…..
  
  When will the vendors learn to look at their stuff first.
  
  Jim Cobane
  
  Henry Ford Health
- May 7, 2009 at 8:16 pm #67791
  Gary Atkinson
  Participant
  The interesting part is the vendor is another engine product (name withheld) 😈
  
  I learn something new everyday because of Cloverleaf (shameless plug 8) )
- May 7, 2009 at 8:52 pm #67792
  Jim Kosloskey
  Participant
  Gary,
  
  As long as it is the truth and not bashing I don’t see any reason not to divulge the product name.
  
  After all, some of us may encounter this product in the future and we would know to make sure they are formatting their acknowledgments properly.
  
  email: jim.kosloskey@jim-kosloskey.com 29+ years Cloverleaf, 59 years IT - old fart.
- May 7, 2009 at 9:26 pm #67793
  Gary Atkinson
  Participant
  I believe its called ensemble.
Author

Replies

Viewing 5 reply threads

The forum ‘Cloverleaf’ is closed to new topics and replies.