Bug 37777

Summary: A single lost packet on a (userland) PPP connection causes long-term disruption and a "storm" of requests and acknowledgements on the CCP layer
Product: Base System Reporter: brett <brett>
Component: binAssignee: Brian Somers <brian>
Status: Closed FIXED    
Severity: Affects Only Me    
Priority: Normal    
Version: 4.5-RELEASE   
Hardware: Any   
OS: Any   

Description brett 2002-05-05 22:10:02 UTC
We are using PPPoE over a wireless connection which very occasionally
drops packets -- typically a few an hour. However, whenever a dropped
packet occurs, the link (which is using "deflate" compression) stalls
for long periods (sometimes seconds, sometimes tens of minutes). Turning
on logging of CCP (set log +ccp) reveals that, instead of resetting the
compression dictionary and gracefully continuing, the two nodes are sending a "storm" of redundant refresh requests and cascading errors. The problem does not seem to be limited to PPPoE or wireless communications, but rather crops up more obviously in these situations because the underlying transport is not reliable. (Modern modems virtually always correct errors unless the connection is dropped completely.) The same problem could crop up on a congested hardwired Ethernet. PPP does not assume a reliable transport, and so should be sufficiently resilient to deal with occasional lost packets.

When a packet is dropped and CCP logging is enabled, the PPP log shows a long stream of messages such as the following. (Note that the first indicates the dropped packet.) The cascade of errors can last for a long time. The glitch from which the messages below are an excerpt continued for more than 10 minutes. (Apologies for the long log excerpt, but it helps to show the severity and longevity of the outage and the thrashing which is occurring.)

May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: DeflateInput: Seq error: Got 397, expected 396
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetReq(5) state = Opened
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetReq(5) state = Opened
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(5) state = Opened
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Input channel reset
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(5) state = Opened
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: deflink: Duplicate ResetAck (resetting again)
May  5 13:19:42 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Input channel reset
May  5 13:20:05 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetReq(187) state = Opened
May  5 13:20:05 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Output channel reset
May  5 13:20:05 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetAck(187) state = Opened
May  5 13:20:05 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetReq(187) state = Opened
May  5 13:20:05 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Output channel reset
May  5 13:20:05 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetAck(187) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: DeflateInput: Seq error: Got 383, expected 382
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetReq(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse last message repeated 3 times
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetReq(188) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Output channel reset
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetAck(188) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetReq(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse last message repeated 5 times
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetReq(188) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Output channel reset
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: SendResetAck(188) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Input channel reset
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Duplicate ResetAck (resetting again)
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: Deflate: Input channel reset
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: RecvResetAck(6) state = Opened
May  5 13:20:19 <daemon.info> workhorse ppp[1067]: CCP: deflink: Unexpected ResetAck (id 6) ignored

[Snip]

Fix: 

None known at this time. At first, we theorized that the problem was specific to the (preferred) "deflate" compression algorithm. However, while connections established using the "predictor-1" algorithm were better behaved, sometimes showed some thrashing behavior as well, with multiple renegotiations after only a single dropped packet.

Turning off ALL compression (by disabling and denying all available algorithms) is a workaround, but a highly inefficent one. (One of our primary motivations for the use of PPPoE is to compress the data stream, of which approximately 30%, according to our measurements, is highly compressible HTML.) Our tests seem to indicate that the problem is most likely in the compression portion of the code -- perhaps the state machine(s) related to CCP. They may also suggest a need for a frame retransmission mechanism within PPP that does not require a complete reset of the compression layer.
How-To-Repeat: Establish a PPPoE or PPP-over-UDP link between two computers and disrupt the link for a brief period. (Alternatively, one may instrument the code so that a packet is blocked now and then on the way to an interface to achieve the same effect.)
Comment 1 dwmalone freebsd_committer freebsd_triage 2002-05-06 09:12:53 UTC
Responsible Changed
From-To: freebsd-bugs->brian

PPP is Brian's.
Comment 2 Brian Somers freebsd_committer freebsd_triage 2002-05-07 10:22:34 UTC
State Changed
From-To: open->closed

As I said in private email: 
: This looks ok.  Each time one side misses a datagram, (Seq error: 
: Got N+1, expected N), it sends a reset request.  Each subsequent 
: packet received before the reset ack will also result in a reset 
: request.  Eventually, after the request has hit the peer, the peer 
: resets it's dictionary and sends a reset ack.  On receipt of the 
: reset ack, the first side can start decompressing again. 
: 
: There will usually be one or two packets in transit when something 
: goes missing, resulting in more than one reset request being sent. 
: It's necessary to send a reset request for each out of sync packet, 
: just in case the previous reset request didn't make it to the peer. 

In the PPPoE case, there may be many packets en route when a problem 
occurs.  This has bad effects on the TCP layer as it has to re-sync 
itself. 

Effectively, compressing an unreliable transport means that an error 
is magnified - one missing datagram becomes many missed datagrams. 
This is unavoidable given the protocol spec.
Comment 3 Brian Somers 2002-05-15 03:03:35 UTC
> At 03:29 AM 5/7/2002, brian@FreeBSD.org wrote:
> 
> >In the PPPoE case, there may be many packets en route when a problem
> >occurs.  This has bad effects on the TCP layer as it has to re-sync
> >itself.
> 
> Do you mean the CCP layer?

No.  The TCP layer has to resync itself when IP datagrams go missing.

> In any event, what we are seeing in the logs is not just one 
> resynchronization but a second as much as several seconds later when 
> the next packet is sent.... As if the first resynch didn't happen 
> correctly. I am not yet convinced that there is not a bug here.
> After all, by the time a second or two has passed, everything should
> be ready for the next packet.

You should see the

CCP: DeflateInput: Seq error: Got N+1, expected N

error (indicating a missing datagram), followed by a CCP ResetRequest 
being sent back to the peer.  All subsequent datagrams will be dropped, 
and another CCP ResetRequest sent, until a CCP ResetAck is received 
at which point you see

CCP: Deflate: Input channel reset.

You'll see up to one such message for each CCP ResetRequest sent 
(where the peer is ACKing the Reset Request and initialising it's 
dictionary).  The number of CCP ResetAcks depends on what the peer 
is sending between receiving the first CCP ResetRequest and receiving 
the last.

If say 10 datagrams are in transit when one disappears, there will be 9 
CCP ResetRequests and 9 dropped datagrams, followed by one or more 
ResetAcks.

The 10 missing datagrams stay missing, so if they belong to one or 
more TCP streams, each TCP stream has to figure out what's happened 
and retransmit.

> >Effectively, compressing an unreliable transport means that an error
> >is magnified - one missing datagram becomes many missed datagrams.
> >This is unavoidable given the protocol spec.
> 
> Is it? Can't the compression layer either provide its own reliable
> transport or get a lower layer to supply it? Should we be using
> a different protocol, such as PPP over TCP (which is really TCP
> over PPP over TCP -- redundant!) or PPTP?

PPP is not a reliable transport.

If you run PPP over TCP it becomes reliable.  There will be no CCP 
errors, but at the expense of having two TCP layers recovering after 
a packet is dropped (assuming a top level TCP layer).  In practice, 
this doesn't hurt as much as you'd expect.

> --Brett

-- 
Brian <brian@Awfulhak.org>                    <brian@freebsd-services.com>
      <http://www.Awfulhak.org>                   <brian@[uk.]FreeBSD.org>
Don't _EVER_ lose your sense of humour !          <brian@[uk.]OpenBSD.org>