DataB3Req before confirming previously received DataB3Ind

[Lothar Kimmeringer]

Hello,

I'm currently sitting on a trace of a data-communication that
sometimes hangs and gets disconnected by the provider due to
an inactivity-timeout. When going through the CAPI-Trace I
can see the following effect:

<------------- Tue Mar 23 03:34:00 CET 2010 93 Message ID: 9f4
--------------------------------------------------------------------------------
Raw length: 30
1e 00 01 00 86 82 f4 09 01 01 01 00 90 24 2d 00 '??????ô??????$-?'
80 00 00 00 00 00 00 00 00 00 00 00 00 00 '??????????????'
--------------------------------------------------------------------------------
DATA_B3_IND 1
Data-Handle = 0x0
Data-Length = 0x80
Flags = 00000000000000000000000000000000
NCCI = 0x10101
Data = 0x2d2490
Data64 = 0x0
[...]
-------------> Tue Mar 23 03:34:00 CET 2010 95 Message ID: 84
--------------------------------------------------------------------------------
Raw length: 30
1e 00 01 00 86 80 84 00 01 01 01 00 c8 c9 87 69 '????????????ÈÉ?i'
0a 00 08 00 00 00 00 00 00 00 00 00 00 00 '??????????????'
--------------------------------------------------------------------------------
DATA_B3_REQ 1
Data-Handle = 0x8
Data-Length = 0xa
Flags = 00000000000000000000000000000000
NCCI = 0x10101
Data = 0x6987c9c8
Data64 = 0x0
-------------> Tue Mar 23 03:34:00 CET 2010 96 Message ID: 9f4
--------------------------------------------------------------------------------
Raw length: 14
0e 00 01 00 86 83 f4 09 01 01 01 00 00 00 '??????ô???????'
--------------------------------------------------------------------------------
DATA_B3_RESP 1
Data-Handle = 0x0
NCCI = 0x10101

So the response to the received data b3 block is sent after sending
a data b3 request (containing the answer to the request being
received with that block. Every time this kind of thing happens,
the connection hangs and gets disconnected one minute later:

<------------- Tue Mar 23 03:35:00 CET 2010 840 Message ID: 9f7
--------------------------------------------------------------------------------
Raw length: 15
0f 00 01 00 84 82 f7 09 01 01 01 00 00 00 00 '??????÷????????'
--------------------------------------------------------------------------------
DISCONNECT_B3_IND 1
B3 Protocol = 0x2 (ISO_8208_X_25_DTE_DTE)
Reason = 0x0 (Normal clearing, no cause available)
NCCI = 0x10101
NCPI = none

Is it against the standard to send a DataB3Request before
responding to a received Indication or is that a bug on my
communication partner's side?


Best regards,

Lothar

[Tilman Schmidt]

Post by Lothar Kimmeringer
Is it against the standard to send a DataB3Request before
responding to a received Indication

The document "COMMON-ISDN-API Version 2.0 4th Edition June 2001"
certainly doesn't forbid it. Sending and receiving are completely
independent according to that document. What's more, forbidding
it would create a race condition because you can never be sure,
when sending a DATA_B3_REQ, that a DATA_B3_IND hasn't arrived
that very instant. It's highly unlikely IMHO that the authors of
the standard would have intended such a situation.

Post by Lothar Kimmeringer
or is that a bug on my
communication partner's side?

Actually I'd rather suspect a bug in your ISDN adapter's CAPI
implementation. Your communication partner probably just times
out because it doesn't see any more activity from you.

I'm assuming that you verified the hang really happens every time
the sequence of events DATA_B3_IND - DATA_B3_REQ - DATA_B3_RESP
occurs, and not just the opposite (that sequence appears in the
trace every time the hang happens).

HTH
Tilman

[Lothar Kimmeringer]

Post by Tilman Schmidt

Post by Lothar Kimmeringer
or is that a bug on my
communication partner's side?

Actually I'd rather suspect a bug in your ISDN adapter's CAPI
implementation.

It's an AVM Fritz! card with corresponding CAPI-driver accessed
by jCAPI. I'm not sure if the system my connector is running
on is Windows or Linux but I assume it's Windows, because of
the set Data-element in DATA_B3_REQ instead of being 0 [1]

Post by Tilman Schmidt
Your communication partner probably just times
out because it doesn't see any more activity from you.

Can't be, because the DataB3Request I quoted is the last thing
I have to do before the partner has to send something again. So
it's not my partner not seeing any activity but me. My theory
is that the Indication being received from the partner instead
of the Confirmation is unexpected and lead to an error
breaking something there. Especially since there is no Confirmation
for the B3-Request coming back, either.

Post by Tilman Schmidt
I'm assuming that you verified the hang really happens every time
the sequence of events DATA_B3_IND - DATA_B3_REQ - DATA_B3_RESP
occurs,

Yes and it happens at different points of time during the
communication. I have a couple of traces and every time
I see a IND-REQ-RESP-combination (and the next thing that
should happen according to the protocol is another IND),
I get a DISCONNECT_IND after one minute.

Every time, there are only IND-RESP-REQ sequences, the
whole communication goes through.

Post by Tilman Schmidt
and not just the opposite (that sequence appears in the
trace every time the hang happens).

Not sure if I understand that sentence correctly (you might
repeat it in german ;-)


Best regards,

Lothar

[1] http://lists.opensuse.org/opensuse-isdn-de/2007-06/msg00009.html

[Tilman Schmidt]

Post by Lothar Kimmeringer

Post by Tilman Schmidt
Actually I'd rather suspect a bug in your ISDN adapter's CAPI
implementation.

It's an AVM Fritz! card with corresponding CAPI-driver accessed
by jCAPI. [...]

Even AVM drivers have been known to contain bugs. :-)

As for jCAPI, I don't know enough about that to judge whether it
could be part of the problem.

Post by Lothar Kimmeringer

Post by Tilman Schmidt
Your communication partner probably just times
out because it doesn't see any more activity from you.

Can't be, because the DataB3Request I quoted is the last thing
I have to do before the partner has to send something again. So
it's not my partner not seeing any activity but me. My theory
is that the Indication being received from the partner instead
of the Confirmation is unexpected and lead to an error
breaking something there. Especially since there is no Confirmation
for the B3-Request coming back, either.

Umm, you are aware that CAPI messages aren't transmitted end-to-end,
but only between your application and the CAPI adapter driver, I hope?
It is entirely possible that the driver chokes on your DATA_B3_REQ
because it is expecting the DATA_B3_RESP first, and therefore never
actually sends the data in your DATA_B3_REQ to your communication
partner.

Post by Lothar Kimmeringer

Post by Tilman Schmidt
I'm assuming that you verified the hang really happens every time
the sequence of events DATA_B3_IND - DATA_B3_REQ - DATA_B3_RESP
occurs,

Yes and it happens at different points of time during the
communication. I have a couple of traces and every time
I see a IND-REQ-RESP-combination (and the next thing that
should happen according to the protocol is another IND),
I get a DISCONNECT_IND after one minute.

That one minute strongly suggests a timeout somewhere, most likely
in the communication protocol. And the DISCONNECT_IND suggests it
is happening on the far end, ie. at your communication partner.
Do you have a chance to trace the communication at the other end,
or get some sort of log file from your communication partner?
That way you might confirm or disprove my theory.

Also, if I understand you correctly, you do not receive a
DATA_B3_CONF for that last DATA_B3_REQ. That would be another
hint that the driver is hung. Given that your DATA_B3_REQ message
does not have the Delivery confirmation bit (bit 2 in the Flags
parameter) set, the driver should reply to it with DATA_B3_CONF
immediately.

Post by Lothar Kimmeringer
Every time, there are only IND-RESP-REQ sequences, the
whole communication goes through.

More evidence for a driver problem. If everything worked as it
should, the difference between IND-RESP-REQ and IND-REQ-RESP
would be completely invisible to your communication partner,
because the RESP CAPI message is consumed by the driver and
never goes out to the ISDN line.

HTH
T.

[Lothar Kimmeringer]

Post by Tilman Schmidt

Post by Lothar Kimmeringer

Post by Tilman Schmidt
Actually I'd rather suspect a bug in your ISDN adapter's CAPI
implementation.

It's an AVM Fritz! card with corresponding CAPI-driver accessed
by jCAPI. [...]

Even AVM drivers have been known to contain bugs. :-)

I'm aware of that ;-)

Post by Tilman Schmidt
As for jCAPI, I don't know enough about that to judge whether it
could be part of the problem.

Don't worry about that. If you check out the people having done
checkins of code lately, you'll see why ;-)

Post by Tilman Schmidt

Post by Lothar Kimmeringer

Post by Tilman Schmidt
Your communication partner probably just times
out because it doesn't see any more activity from you.

Can't be, because the DataB3Request I quoted is the last thing
I have to do before the partner has to send something again. So
it's not my partner not seeing any activity but me. My theory
is that the Indication being received from the partner instead
of the Confirmation is unexpected and lead to an error
breaking something there. Especially since there is no Confirmation
for the B3-Request coming back, either.

Umm, you are aware that CAPI messages aren't transmitted end-to-end,
but only between your application and the CAPI adapter driver, I hope?

I'm aware of that.

Post by Tilman Schmidt
It is entirely possible that the driver chokes on your DATA_B3_REQ
because it is expecting the DATA_B3_RESP first, and therefore never
actually sends the data in your DATA_B3_REQ to your communication
partner.

If this is the case, it should have happened in one of the many tests
I'm doing here with AVM on one side and e.g. Bianca Brick on the other.
There were a lot of (strange) things happening concerning when CONFs
were received after sending REQs, but that never was one of them.
But I will set up a unit test where I simulate that to see if the
choking happens there as well.

Post by Tilman Schmidt

Post by Lothar Kimmeringer

Post by Tilman Schmidt
I'm assuming that you verified the hang really happens every time
the sequence of events DATA_B3_IND - DATA_B3_REQ - DATA_B3_RESP
occurs,

Yes and it happens at different points of time during the
communication. I have a couple of traces and every time
I see a IND-REQ-RESP-combination (and the next thing that
should happen according to the protocol is another IND),
I get a DISCONNECT_IND after one minute.

That one minute strongly suggests a timeout somewhere, most likely
in the communication protocol.

The disconnect comes from the driver/provider. Here's the part
from the trace:

-------------> Tue Mar 23 03:11:36 CET 2010 915 Message ID: 9db
--------------------------------------------------------------------------------
Raw length: 14
0e 00 01 00 86 83 db 09 01 04 01 00 00 00
'??????Û???????'
--------------------------------------------------------------------------------
DATA_B3_RESP 1
Data-Handle = 0x0
NCCI = 0x10401
================================================================================
<------------- Tue Mar 23 03:12:37 CET 2010 760 Message ID: 9dc
--------------------------------------------------------------------------------
Raw length: 15
0f 00 01 00 08 82 dc 09 01 04 00 00 45 80 00
'??????Ü?????E??'
--------------------------------------------------------------------------------
INFO_IND 1
Info Number = 0xffff8045
PLCI = 0x401
Element =
Network event message (Q.931): DISCONNECT
================================================================================
-------------> Tue Mar 23 03:12:37 CET 2010 765 Message ID: 9dc
--------------------------------------------------------------------------------
Raw length: 12
0c 00 01 00 08 83 dc 09 01 04 00 00 '??????Ü?????'
--------------------------------------------------------------------------------
INFO_RESP 1
PLCI = 0x401
================================================================================
<------------- Tue Mar 23 03:12:37 CET 2010 765 Message ID: 9dd
--------------------------------------------------------------------------------
Raw length: 17
11 00 01 00 08 82 dd 09 01 04 00 00 08 00 02 80
'??????Ý?????????'
90 '?'
--------------------------------------------------------------------------------
INFO_IND 1
Info Number = 0x8
PLCI = 0x401
Element =
Info (Q.931): CAUSE
80 90
================================================================================
-------------> Tue Mar 23 03:12:37 CET 2010 766 Message ID: 9dd
--------------------------------------------------------------------------------
Raw length: 12
0c 00 01 00 08 83 dd 09 01 04 00 00 '??????Ý?????'
--------------------------------------------------------------------------------
INFO_RESP 1
PLCI = 0x401
================================================================================
<------------- Tue Mar 23 03:12:37 CET 2010 766 Message ID: 9de
--------------------------------------------------------------------------------
Raw length: 15
0f 00 01 00 84 82 de 09 01 04 01 00 00 00 00
'??????Þ????????'
--------------------------------------------------------------------------------
DISCONNECT_B3_IND 1
B3 Protocol = 0x2 (ISO_8208_X_25_DTE_DTE)
Reason = 0x0 (Normal clearing, no cause available)
NCCI = 0x10401
NCPI = none

A disconnect coming from the peer would require one last DataB3Indication
containing the "End of Line"-information.

Post by Tilman Schmidt
And the DISCONNECT_IND suggests it
is happening on the far end, ie. at your communication partner.

Or the provider.

Post by Tilman Schmidt
Do you have a chance to trace the communication at the other end,
or get some sort of log file from your communication partner?

The communication-partner of my customer is already requesting that
from their software-supplier forwarding my mail with the parts of
the trace I was giving here as well. Problem is that their traces
are far less verbose than mine, so I'm not sure if you can see the
CAPI-messages in such a detail.

Post by Tilman Schmidt
Also, if I understand you correctly, you do not receive a
DATA_B3_CONF for that last DATA_B3_REQ. That would be another
hint that the driver is hung. Given that your DATA_B3_REQ message
does not have the Delivery confirmation bit (bit 2 in the Flags
parameter) set, the driver should reply to it with DATA_B3_CONF
immediately.

Is that protocol-independent? The connection in question
is X.25 DTE DTE on B3.

Post by Tilman Schmidt

Post by Lothar Kimmeringer
Every time, there are only IND-RESP-REQ sequences, the
whole communication goes through.

More evidence for a driver problem. If everything worked as it
should, the difference between IND-RESP-REQ and IND-REQ-RESP
would be completely invisible to your communication partner,
because the RESP CAPI message is consumed by the driver and
never goes out to the ISDN line.

If I'm right and the driver needs to wait for the confirmation
from the peer due to the B3-protocol setting even without being
explicitly set in the Data-block, a problem in the local driver
is not the only possible reason.

I wait for the response from the other software vendor.


Thanks, Lothar

[Tilman Schmidt]

Post by Lothar Kimmeringer

Post by Tilman Schmidt
That one minute strongly suggests a timeout somewhere, most likely
in the communication protocol.

The disconnect comes from the driver/provider. Here's the part
-------------> Tue Mar 23 03:11:36 CET 2010 915 Message ID: 9db
--------------------------------------------------------------------------------
Raw length: 14
0e 00 01 00 86 83 db 09 01 04 01 00 00 00
'??????Û???????'
--------------------------------------------------------------------------------
DATA_B3_RESP 1
Data-Handle = 0x0
NCCI = 0x10401
================================================================================
<------------- Tue Mar 23 03:12:37 CET 2010 760 Message ID: 9dc
--------------------------------------------------------------------------------
Raw length: 15
0f 00 01 00 08 82 dc 09 01 04 00 00 45 80 00
'??????Ü?????E??'
--------------------------------------------------------------------------------
INFO_IND 1
Info Number = 0xffff8045
PLCI = 0x401
Element =
Network event message (Q.931): DISCONNECT
================================================================================

That contradicts your statement. "Network event message: DISCONNECT" indicates
rather clearly that the disconnect came in over the S0 interface. So it was
either emitted by the communication partner, or generated by the network itself.

Post by Lothar Kimmeringer
-------------> Tue Mar 23 03:12:37 CET 2010 765 Message ID: 9dc
--------------------------------------------------------------------------------
Raw length: 12
0c 00 01 00 08 83 dc 09 01 04 00 00 '??????Ü?????'
--------------------------------------------------------------------------------
INFO_RESP 1
PLCI = 0x401
================================================================================
<------------- Tue Mar 23 03:12:37 CET 2010 765 Message ID: 9dd
--------------------------------------------------------------------------------
Raw length: 17
11 00 01 00 08 82 dd 09 01 04 00 00 08 00 02 80
'??????Ý?????????'
90 '?'
--------------------------------------------------------------------------------
INFO_IND 1
Info Number = 0x8
PLCI = 0x401
Element =
Info (Q.931): CAUSE
80 90
================================================================================

That's cause code 10 "Normal Call Clearing". IOW the network says "it's not my
fault, your communication partner hung up".

Post by Lothar Kimmeringer
-------------> Tue Mar 23 03:12:37 CET 2010 766 Message ID: 9dd
--------------------------------------------------------------------------------
Raw length: 12
0c 00 01 00 08 83 dd 09 01 04 00 00 '??????Ý?????'
--------------------------------------------------------------------------------
INFO_RESP 1
PLCI = 0x401
================================================================================
<------------- Tue Mar 23 03:12:37 CET 2010 766 Message ID: 9de
--------------------------------------------------------------------------------
Raw length: 15
0f 00 01 00 84 82 de 09 01 04 01 00 00 00 00
'??????Þ????????'
--------------------------------------------------------------------------------
DISCONNECT_B3_IND 1
B3 Protocol = 0x2 (ISO_8208_X_25_DTE_DTE)
Reason = 0x0 (Normal clearing, no cause available)
NCCI = 0x10401
NCPI = none
A disconnect coming from the peer would require one last DataB3Indication
containing the "End of Line"-information.

Why do you think so? If the peer's protocol engine comes to the conclusion
that you are dead or something else has horribly gone wrong and there's no
point in even trying to talk to you anymore, it may just as well without
any further ado emit a DISCONNECT_B3_REQ to its CAPI provider (provided it
is even using CAPI), which will show up at your end exactly as the
sequence you reported above.

Post by Lothar Kimmeringer

Post by Tilman Schmidt
Do you have a chance to trace the communication at the other end,
or get some sort of log file from your communication partner?

The communication-partner of my customer is already requesting that
from their software-supplier forwarding my mail with the parts of
the trace I was giving here as well. Problem is that their traces
are far less verbose than mine, so I'm not sure if you can see the
CAPI-messages in such a detail.

We don't need CAPI messages (and if the other end doesn't use CAPI
there won't even be any). What I'd like to know is if the peer does
actively hang up, and why. I'm hoping for a log entry along the lines
of "connection timed out, no response from peer" or similar.

Post by Lothar Kimmeringer

Post by Tilman Schmidt
Also, if I understand you correctly, you do not receive a
DATA_B3_CONF for that last DATA_B3_REQ. That would be another
hint that the driver is hung. Given that your DATA_B3_REQ message
does not have the Delivery confirmation bit (bit 2 in the Flags
parameter) set, the driver should reply to it with DATA_B3_CONF
immediately.

Is that protocol-independent? The connection in question
is X.25 DTE DTE on B3.

AFAIK yes, but I don't have any experience with X.25.

HTH
Tilman

[Jochen]

Dear Lothar,

I cant see anything in the short trace which is realy incorrect.
A gues would be havin a look at the messagebuffer Size and the
MaxBDataBlocks in CAPIRegister.
The formula for the MesgBufferSize is given in the CAPI docs, for
MaxBDataBlocks I´d suggest 7.
Did you test with different Devices, differnet CAPI Implementations?
Same behavior on different devices?

Regards,
Jochen Klein
www.servonic.com

Post by Lothar Kimmeringer
Hello,
I'm currently sitting on a trace of a data-communication that
sometimes hangs and gets disconnected by the provider due to
an inactivity-timeout. When going through the CAPI-Trace I
<------------- Tue Mar 23 03:34:00 CET 2010 93 Message ID: 9f4
--------------------------------------------------------------------------------
Raw length: 30
1e 00 01 00 86 82 f4 09 01 01 01 00 90 24 2d 00 '??????ô??????$-?'
80 00 00 00 00 00 00 00 00 00 00 00 00 00 '??????????????'
--------------------------------------------------------------------------------
DATA_B3_IND 1
Data-Handle = 0x0
Data-Length = 0x80
Flags = 00000000000000000000000000000000
NCCI = 0x10101
Data = 0x2d2490
Data64 = 0x0
[...]
-------------> Tue Mar 23 03:34:00 CET 2010 95 Message ID: 84
--------------------------------------------------------------------------------
Raw length: 30
1e 00 01 00 86 80 84 00 01 01 01 00 c8 c9 87 69 '????????????ÈÉ?i'
0a 00 08 00 00 00 00 00 00 00 00 00 00 00 '??????????????'
--------------------------------------------------------------------------------
DATA_B3_REQ 1
Data-Handle = 0x8
Data-Length = 0xa
Flags = 00000000000000000000000000000000
NCCI = 0x10101
Data = 0x6987c9c8
Data64 = 0x0
-------------> Tue Mar 23 03:34:00 CET 2010 96 Message ID: 9f4
--------------------------------------------------------------------------------
Raw length: 14
0e 00 01 00 86 83 f4 09 01 01 01 00 00 00 '??????ô???????'
--------------------------------------------------------------------------------
DATA_B3_RESP 1
Data-Handle = 0x0
NCCI = 0x10101
So the response to the received data b3 block is sent after sending
a data b3 request (containing the answer to the request being
received with that block. Every time this kind of thing happens,
<------------- Tue Mar 23 03:35:00 CET 2010 840 Message ID: 9f7
--------------------------------------------------------------------------------
Raw length: 15
0f 00 01 00 84 82 f7 09 01 01 01 00 00 00 00 '??????÷????????'
--------------------------------------------------------------------------------
DISCONNECT_B3_IND 1
B3 Protocol = 0x2 (ISO_8208_X_25_DTE_DTE)
Reason = 0x0 (Normal clearing, no cause available)
NCCI = 0x10101
NCPI = none
Is it against the standard to send a DataB3Request before
responding to a received Indication or is that a bug on my
communication partner's side?
Best regards,
Lothar

[Lothar Kimmeringer]

Hi Jochen,

Post by Jochen
I cant see anything in the short trace which is realy incorrect.

I can't provide much more than that due to the fact, that this
would reveal informations I'm not allowed to publish.

Post by Jochen
A gues would be havin a look at the messagebuffer Size and the
MaxBDataBlocks in CAPIRegister.
The formula for the MesgBufferSize is given in the CAPI docs, for
MaxBDataBlocks I´d suggest 7.

Running out of buffers is not the case here. Until that point
there are no other unconfirmed data blocks and if the sequence
of messages is IND-RESP-REQ, the data-transfer later on will
lead to up to 6 unconfirmed data blocks. This works fine.

Post by Jochen
Did you test with different Devices, differnet CAPI Implementations?

In general yes, but the problem occurs on a productive running
system, so I have a specific combination of device and driver
I can't change easily.

Post by Jochen
Same behavior on different devices?

This is the first time I see something like this in a trace
and there are hundreds of others running fine, even with the
same software-vendor on the "other" side. Question is, who
is violating the CAPI to bring the discussion of "how to solve
that" further. At the moment both sides only claim "it works
fine for others, so it's your problem" ;-)


Best regards,

Lothar

[Jochen]

Post by Lothar Kimmeringer
Hi Jochen,

Post by Jochen
A gues would be havin a look at the messagebuffer Size and the
MaxBDataBlocks in CAPIRegister.
The formula for the MesgBufferSize is given in the CAPI docs, for
MaxBDataBlocks I´d suggest 7.

Running out of buffers is not the case here. Until that point
there are no other unconfirmed data blocks and if the sequence
of messages is IND-RESP-REQ, the data-transfer later on will
lead to up to 6 unconfirmed data blocks. This works fine.

o.k., was just a hint/guess.

Post by Lothar Kimmeringer

Post by Jochen
Did you test with different Devices, differnet CAPI Implementations?

In general yes, but the problem occurs on a productive running
system, so I have a specific combination of device and driver
I can't change easily.

So it is not a general problem, but one which occours in a specific
environment.

Post by Lothar Kimmeringer

Post by Jochen
Same behavior on different devices?

This is the first time I see something like this in a trace
and there are hundreds of others running fine, even with the
same software-vendor on the "other" side.

Well so the whole thing is working.

Question is, who

Post by Lothar Kimmeringer
is violating the CAPI to bring the discussion of "how to solve
that" further. At the moment both sides only claim "it works
fine for others, so it's your problem" ;-)

So the most easy and cheap way is chnagingthe ISDN adapter (differnet
model or vendor).
Mosttimes cheaper than spening man hours or even days.

Regards,
Jochen Klein