LCP replies lost?

[Alex Suykov]

Hello,
I'm trying to set up a GPRS connection, and I'm stuck at strange pppd
behavior.
At first glance it looks like connection problem -- pppd dies due to
LCP timeout:

(....)
Serial connection established.
using channel 4
Using interface ppp0
Connect: ppp0 <--> /dev/pts/1
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2788d800> <pcomp>
<accomp>]
(....)
LCP: timeout sending Config-Requests

But if I add record option and unpack resulting file with pppdump,
replies *are* there:

(...)
rcvd "\0d\0aCONNECT\0d\0a"
sent "\0d"
time 0.1s
rcvd "~\ff}#\c0!}!\c5} }<}!}$}%\dc}\"}&} } } }}$\c0#}%}&} }&\bb\f2}'}
\"}(}\"
\ab~"
time 1.0s
sent "~\ff}#\c0!}!}!} }4}\"}&} } } } }%}&'\88\d8} }'}\"}(}\"\bb}'~"
time 0.1s
rcvd "~\ff}#\c0!}\"}!} }4}\"}} } } }%}&'\88\d8} }'}\"}(}\"Pn~"
time 3.8s
rcvd "~\ff}#\c0!}!\c5} }<}!}$}\"}&} } } } }#}$\c0#}%}&} }&\bb\f2}"
rcvd "'}\"}(}\"K\ab~"
time 4.1s
sent "~\ff}#\c0!}!}!} }4}\"}&} } } } }%}&'\88\d8} }'}\"}(}\"\bb}'~"
rcvd "~\ff}#\c0!}\"}!} }4}\"}&} } } } }%}&'}'}\"}(}\"Pn~"
(...)

What's happening, why pppd ignores incoming data? Maybe there's
something wrong with replies -- is there any way to check this?

I tried setting receive-all option, to no avail. Flow control options
have no visible effect too.

Ocassionally I do get replies, usually only one reply per session,
with overall rate 1 received per ~100 sent.

[James Carlson]

Post by Alex Suykov
But if I add record option and unpack resulting file with pppdump,

That's a good indication that the packets are garbled in transit.
Debugging this depends a bit on which OS you're using. It'd be good
to include that sort of background information.

Post by Alex Suykov
rcvd "~\ff}#\c0!}\"}!} }4}\"}&} } } } }%}&'}'}\"}(}\"Pn~"

That looks like a garbage packet to me. I decode that as:

FF 03 C0 21 02 01 00 14 02 06 00 00 00 00 05 06 27 07 02 08 02 50 6E

It looks like three bytes were just dropped out of the middle (at
around the byte value 27 -- in the middle of the LCP Magic Number
option). The rest looks plausible.

Post by Alex Suykov
What's happening, why pppd ignores incoming data? Maybe there's
something wrong with replies -- is there any way to check this?

It depends on the OS and drivers in use.

Post by Alex Suykov
Ocassionally I do get replies, usually only one reply per session,
with overall rate 1 received per ~100 sent.

This is a low-level driver problem ... not really a PPP problem, as
best I can tell.

[Alex Suykov]

Post by James Carlson
That's a good indication that the packets are garbled in transit.
Debugging this depends a bit on which OS you're using. It'd be good
to include that sort of background information.

I'm running linux 2.6.26. The device, Sony Ericsson GC86, is handled
by
standard serial driver (8250.ko, I guess). This is what I see in
syslog:

ttyS0 at I/O 0x2000 (irq = 18) is a 16550A

and here's setserial -a output:

/dev/ttyS0, Line 0, UART: 16550A, Port: 0x2000, IRQ: 18
Baud_base: 230400, close_delay: 50, divisor: 0
closing_wait: 3000
Flags: spd_normal skip_test

I must set port speed in minicom to halved baud_base (115200 for this
case)
to get it work, and it's the only speed it works with. Don't know if
it's relevant,
but at least it's different from real serial port with real dialup
modem attached.

Post by James Carlson
FF 03 C0 21 02 01 00 14 02 06 00 00 00 00 05 06 27 07 02 08 02 50 6E
It looks like three bytes were just dropped out of the middle (at
around the byte value 27 -- in the middle of the LCP Magic Number
option). The rest looks plausible.

Can you expalin this? I'm not a PPP expert to say the least, just read
some
of RFC 1661, and I see C0 21 must be LCP protocol code, 02 is
Configure-Ack,
so 00 14 must be the length of the part starting at 02 01 till the end
of packet.
0x14 is 20, and there's 19 bytes from 02 01 till the end.

Also, it is ok to have garbage before C0 21?

[James Carlson]

Post by Alex Suykov
I must set port speed in minicom to halved baud_base (115200 for this
case)
to get it work, and it's the only speed it works with. Don't know if
it's relevant,
but at least it's different from real serial port with real dialup
modem attached.

That sounds like an interesting clue. Flow control trouble would
cause these sorts of symptoms.

Post by Alex Suykov

Post by James Carlson
FF 03 C0 21 02 01 00 14 02 06 00 00 00 00 05 06 27 07 02 08 02 50 6E
It looks like three bytes were just dropped out of the middle (at
around the byte value 27 -- in the middle of the LCP Magic Number
option). The rest looks plausible.

Can you expalin this? I'm not a PPP expert to say the least, just read
some
of RFC 1661, and I see C0 21 must be LCP protocol code, 02 is
Configure-Ack,
so 00 14 must be the length of the part starting at 02 01 till the end
of packet.
0x14 is 20, and there's 19 bytes from 02 01 till the end.
Also, it is ok to have garbage before C0 21?

That part is not garbage. FF 03 is the standard HDLC header. See RFC
1662.

The garbage part comes with 05 06 ... that should have had 4 bytes
following (the header is two bytes, and total option length of 6), but
there's only one byte following (the 27) before the final two options
are seen. Then there's the CRC, which doesn't check out at all -- if
the preceding bytes had been right, then those last two bytes should
have been E0 78, not 50 6E.

The packet is obviously trashed, and the damage looks like lost bytes,
which would implicate either flow control or the integrity of the
serial driver itself.