PDL problem x12 271 response in

This topic has 0 replies, 1 voice, and was last updated 12 years ago by Joe Grathoff.

Creator

Topic
January 4, 2013 at 6:55 pm #53450
Joe Grathoff
Participant
PDL seems to delay reading from the socket until about 38 seconds after message has been posted. The sending host is timing out waiting for the ACK. Does anyone know what is causing the delay. See process log below. I see after the message arriving on the socket at 11:54:47 but the read from the socket does not occur until 11:55:25. I also have the text of the PDL below which is using start character hex 02 and end character hex 03 . Thanks! Joe.

============================================

Portions of process log:

[pti :sche:DBUG/2:loxogon_rte_response_in:01/04/2013 11:54:47] Thread 3 has been

enabled

[pti :sche:INFO/1:loxogon_rte_response_in:01/04/2013 11:54:47] Thread has 1 read

y events.

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:54:47] Processing SOCKET

(PDL server) event 0x2157a6d8

[pti :even:DBUG/1:loxogon_rte_response_in:01/04/2013 11:54:47] Calling cb 0x200b

1c3c

[pdl :read:DBUG/2:loxogon_rte_response_in:01/04/2013 11:54:47] Events: E 0, R 8,

W 0

[pdl :PDL :DBUG/1:loxogon_rte_response_in:01/04/2013 11:55:25] Clearing PDL list

en event

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Unregistering SOC

KET (PDL server) event 0x2157a6d8 for tid 3

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] evUnregister SOCK

ET event 0x2157A6D8 for tid 3

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] accepted fd = 72

[pdl :PDL :DBUG/1:loxogon_rte_response_in:01/04/2013 11:55:25] Creating PDL list

en event on fd 72

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Registering SOCKE

T (PDL server) event 0x2157a6d8 for tid 3

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Registering SOCKE

T event for tid 3

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Calling Tcl proce

dure: hci_pd.default.open-ok

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] with args: {{clie

nt “12.130.100.148”} {status ok}}

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Tcl procedure hci

_pd.default.open-ok returns ”

[pdl :PDL :DBUG/2:loxogon_rte_response_in:01/04/2013 11:55:25] PDL changed state

s: old 4, new 0

[pdl :init:DBUG/1:loxogon_rte_response_in:01/04/2013 11:55:25] PDL did initializ

e: code = 0

[pd :pdtd:INFO/1:loxogon_rte_response_in:01/04/2013 11:55:25] Set driver status

to PD_STATUS_UP

[pti :sche:INFO/1:loxogon_rte_response_in:01/04/2013 11:55:25] Thread has 0 read

y events left.

………

[pti :sele:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Fd 72 ready for READ by thr

ead loxogon_rte_response_in

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag fds free 0x21b51248

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Skipped SOCKET event 0x2157

a6d8; not CLEAR

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag el free 0x214d3588

[pti :sche:INFO/2: rte2_cmd:01/04/2013 11:55:25] Thread 3 is on deck.

[pti :sche:INFO/1: rte2_cmd:01/04/2013 11:55:25] PTI Sched giving thread 3 a

chance

[pti :sche:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Scheduler enabling a SCHED_

IDLE thread

[pti :sche:DBUG/2:loxogon_rte_response_in:01/04/2013 11:55:25] Thread 3 has been

enabled

[pti :sche:INFO/1:loxogon_rte_response_in:01/04/2013 11:55:25] Thread has 2 read

y events.

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Processing ACTIVE

_TIMER () event 0x21494ea8

[pti :even:DBUG/1:loxogon_rte_response_in:01/04/2013 11:55:25] Calling cb 0x200b

226c

[msi :msi :DBUG/1:loxogon_rte_response_in:01/04/2013 11:55:25] msiExportStats: e

xport for thread: loxogon_rte_response_in

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Unregistering ACT

IVE_TIMER () event 0x21494ea8 for tid 3

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] evUnregister ACTI

VE_TIMER event 0x21494EA8 for tid 3

[diag:leak:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] diag timeval allo

c 0x20fa22d8

[diag:leak:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] diag dqe alloc 0x

214bc6b8

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Registering ACTIV

E_TIMER () event 0x21494ea8 for tid 3

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Registering ACTIV

E_TIMER event for tid 3

[diag:leak:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] diag timeval free

0x20fa22d8

[pti :sche:INFO/1:loxogon_rte_response_in:01/04/2013 11:55:25] Thread has 1 read

y events left.

[pti :even:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Checking for polled events

[pti :even:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Checking for polled events

[xlt :xlat:INFO/1: rte2_xlate:01/04/2013 11:55:25] Checking xlate queues

xlate: # msg = 0; try = 1; force = 0

[pti :even:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Checking for polled events

[pti :even:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Checking for polled events

[pti :even:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Checking for polled events

[pti :even:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Checking for polled events

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag timeval alloc 0x20fa22

d8

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag timeval free 0x20fa22

d8

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Thread 0 isn’t runnable.

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Thread 1 isn’t runnable.

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Thread 2 isn’t runnable.

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Thread 3 is runnable.

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Thread 4 isn’t runnable.

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Thread 5 isn’t runnable.

[pti :sche:INFO/0: rte2_cmd:01/04/2013 11:55:25] Non-blocking select().

[pti :sele:DBUG/0: rte2_cmd:01/04/2013 11:55:25] Non-blocking select().

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag fds alloc 0x21b51248

[pti :sele:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Select sets after: NFDS = 1

in [7:72], NMSGS = 0 of 0

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag el alloc 0x2157a718 n

um 73

[pti :sele:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Fd 72 ready for READ by thr

ead loxogon_rte_response_in

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag fds free 0x21b51248

[pti :sche:DBUG/3: rte2_cmd:01/04/2013 11:55:25] Skipped SOCKET event 0x2157

a6d8; not CLEAR

[diag:leak:DBUG/0: rte2_cmd:01/04/2013 11:55:25] diag el free 0x2157a718

[pti :sche:INFO/2: rte2_cmd:01/04/2013 11:55:25] Thread 3 is on deck.

[pti :sche:INFO/1: rte2_cmd:01/04/2013 11:55:25] PTI Sched giving thread 3 a

chance

[pti :sche:DBUG/1: rte2_cmd:01/04/2013 11:55:25] Scheduler enabling a SCHED_

IDLE thread

[pti :sche:DBUG/2:loxogon_rte_response_in:01/04/2013 11:55:25] Thread 3 has been

enabled

[pti :sche:INFO/1:loxogon_rte_response_in:01/04/2013 11:55:25] Thread has 1 read

y events.

[pti :even:DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Processing SOCKET

(PDL server) event 0x2157a6d8

[pti :even:DBUG/1:loxogon_rte_response_in:01/04/2013 11:55:25] Calling cb 0x200b

1c3c

[pdl :read:DBUG/2:loxogon_rte_response_in:01/04/2013 11:55:25] Events: E 0, R 8,

W 0

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] read 491 bytes

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] input buffer acce

pted 491 bytes, now 491

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 02 49 53 41 2a

30 30 2a |.ISA*00*|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 20 20 20 20 20

20 20 20 | |

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 20 20 2a 30 30

2a 20 20 | *00* |

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 20 20 20 20 20

20 20 20 | |

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 5a 5a 2a 4c

4f 58 4f |*ZZ*LOXO|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 47 4f 4e 20 20

20 20 20 |GON |

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 20 20 20 2a 5a

5a 2a 48 | *ZZ*H|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 55 52 4c 45 59

54 20 20 |URLEYT |

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 20 20 20 20 20

20 2a 31 | *1|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 33 30 31 30 34

2a 31 30 |30104*10|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 35 34 2a 5e 2a

30 30 35 |54*^*005|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 31 2a 30 30

30 30 30 |01*00000|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 32 38 39 32 2a

31 2a 54 |2892*1*T|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 3a 7e 47 53

2a 48 42 |*:~GS*HB|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 4c 4f 58 4f

47 4f 4e |*LOXOGON|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 48 55 52 4c

45 59 54 |*HURLEYT|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 31 33 30 31

30 34 2a |*130104*|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 31 30 35 34 2a

32 38 39 |1054*289|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 32 2a 58 2a 30

30 35 30 |2*X*0050|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 31 30 58 32 37

39 41 31 |10X279A1|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 7e 53 54 2a 32

37 31 2a |~ST*271*|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 32 38 39 32 2a

30 30 35 |2892*005|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 31 30 58 32

37 39 41 |010X279A|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 31 7e 42 48 54

2a 30 30 |1~BHT*00|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 32 32 2a 31 31

2a 45 50 |22*11*EP|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 49 43 20 39 39

34 32 37 |IC 99427|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 20 34 33 36

20 54 53 |0 436 TS|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 54 2a 32 30 31

33 30 31 |T*201301|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 34 2a 31 36

35 34 7e |04*1654~|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 48 4c 2a 31 2a

2a 32 30 |HL*1**20|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 31 7e 4e 4d

31 2a 50 |*1~NM1*P|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 52 2a 32 2a 42

43 42 53 |R*2*BCBS|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 20 4f 46 20 4d

49 43 48 | OF MICH|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 49 47 41 4e 2a

2a 2a 2a |IGAN****|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 50 49 2a 30

30 32 31 |*PI*0021|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 7e 48 4c 2a

32 2a 31 |0~HL*2*1|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 32 31 2a 31

7e 4e 4d |*21*1~NM|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 31 2a 31 50 2a

32 2a 48 |1*1P*2*H|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 55 52 4c 45 59

20 4d 45 |URLEY ME|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 44 49 43 41 4c

20 43 45 |DICAL CE|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 4e 54 45 52 2a

2a 2a 2a |NTER****|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 58 58 2a 31

35 39 38 |*XX*1598|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 37 31 37 34 38

30 7e 48 |717480~H|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 4c 2a 33 2a 32

2a 32 32 |L*3*2*22|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 30 7e 4e 4d

31 2a 49 |*0~NM1*I|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 4c 2a 31 2a 43

41 44 55 |L*1*CADU|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 53 54 2a 54 57

45 4e 54 |ST*TWENT|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 59 45 49 47 48

54 41 2a |YEIGHTA*|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 2a 2a 4d 49

2a 54 41 |***MI*TA|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 43 31 32 33 34

35 36 37 |C1234567|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 38 39 7e 41 41

41 2a 59 |89~AAA*Y|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 2a 37 38 2a

43 7e 44 |**78*C~D|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 4d 47 2a 44 38

2a 31 39 |MG*D8*19|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 37 33 30 31 30

33 2a 4d |730103*M|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 7e 44 54 50 2a

32 39 31 |~DTP*291|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 2a 44 38 2a 32

30 31 33 |*D8*2013|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 31 30 34 7e

53 45 2a |0104~SE*|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 31 32 2a 32 38

39 32 7e |12*2892~|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 47 45 2a 31 2a

32 38 39 |GE*1*289|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 32 7e 49 45 41

2a 31 2a |2~IEA*1*|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 30 30 30 30 30

32 38 39 |00000289|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] 32 7e 03

|2~.|

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] IDLE and 491 byte

s but no error: starting READ

[pdl :PDL :DBUG/2:loxogon_rte_response_in:01/04/2013 11:55:25] PDL changed state

s: old 0, new 1

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Calling Tcl proce

dure: hci_pd.read

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] with args: {}

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Tcl procedure hci

_pd.read returns ‘RECEIVE’

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] trying to match p

hrase: basic-msg

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] multi_phrase_2: s

tatus = ok

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] Calling Tcl proce

dure: read.done

[pdl :PDL :DBUG/0:loxogon_rte_response_in:01/04/2013 11:55:25] with args: {{stat

us ok} {end {491 0}} {data {1 489}}}

====================================

PDL:

/* $Id: loxogonx12_tcp.pdl,v 1.3 2013/1/3 00:05:27 neuts Exp $ */

/*

* Copyright 2002, McKesson under license from Quovadx, Inc.

*

* loxogonx12_tcp.pdl – TCP/IP Protocol for Loxogon X12 transmision

*/

define driver loxogonx12tcp;

version: “2.0”;

end driver;

/* This driver manages the transmission of messages using the X12 defined

* TCP protocol. Each message is bounded by a start character HEX-02

* and a stop string HEX-03.

*

* The phrase basic-msg recognizes this message format. Once recognized,

* the message data will be available from the ‘data’ field.

*/

define phrase basic-msg;

;

field data = variable-array( not( ) );

;

end phrase;

/**********************************************************************

* End of declarative section, TCL management functions start here. *

**********************************************************************/

#{#

# This can be handled completely using the “basic” style.

hci_pd_msg_style basic phrase:basic-msg

field:data

resync:\xb

#}#

==============================================

Message from tcpdump showing start and stop characters.

0x0000 4500 0213 73f6 0000 7e06 4998 0c82 6494 E…s
Creator

Topic

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