Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Andrew Morton]

(switch to email - please retain all ccs)

On Sun, 29 Apr 2007 13:01:25 -0700 bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=8405
> 
>            Summary: pppd does stops compresion with "Lost compression sync"
>     Kernel Version: 2.6.18-2.6.21
>             Status: NEW
>           Severity: normal
>              Owner: other_modules@kernel-bugs.osdl.org
>          Submitter: stefan.wenk@gmx.at
> 
> 
> Most recent kernel where this bug did *NOT* occur:2.6.17
> Distribution: Fedora core 3
> Hardware Environment:
> Software Environment:
> Problem Description:
> I have the same problem as reported on
> http://www.luga.at/mailing-lists/luga/2007/02/msg00032.html (in German).
> When I connect to my ISP via an analogue serial modem my Linux Box sends a PPP
> Compression Control Protocol Termination Request with  "Lost compression sync"
> to the provider and then the provider dropps the link. This does not happen with
> kernel
> 2.6.17, but happens from kernel version 2.6.18 to 2.6.21 (not tested: 2.6.19).
> If I put the nodeflate command line to the pppd then the link remains stable.
> Steps to reproduce:
> In order to find out what is happening I have set up a ppp connection via a
> serial nullmodem to another old Linux box (kernel 2.2.14) and have activated the
> kernel debug in the ppp_deflate.ko module. The "Lost compression sync:" is
> reproducable in this configuration - the only difference is that the link
> remains (without deflate compression).
> 
> Here is the log vor /var/log/messages:
> 
> Apr 29 16:53:34 linux kernel: PPP Deflate Compression module registered
> Apr 29 16:53:47 linux pppd[9090]: pppd 2.4.4 started by root, uid 0
> Apr 29 16:53:47 linux pppd[9090]: Using interface ppp0
> Apr 29 16:53:47 linux pppd[9090]: Connect: ppp0 <--> /dev/pts/9
> Apr 29 16:53:47 linux pppd[9090]: kernel does not support PPP filtering
> Apr 29 16:53:47 linux pppd[9090]: Deflate (15) compression enabled
> Apr 29 16:53:47 linux pppd[9090]: Cannot determine ethernet address for proxy ARP
> Apr 29 16:53:47 linux pppd[9090]: local  IP address 192.168.3.2
> Apr 29 16:53:47 linux pppd[9090]: remote IP address 192.168.3.1
> Apr 29 16:54:03 linux kernel: z_decompress0: inflate returned -5 ()
> Apr 29 16:54:03 linux pppd[9090]: PPPIOCGFLAGS flags: c030c0
> Apr 29 16:54:03 linux pppd[9090]: Lost compression sync: disabling compression
> 
> I had a look at the kernel patch of 2.6.18 - the lib/zlib/zlib_inflate was
> changed a lot and for me it looks to be the reason of the problem.

If you're referring to 4f3865fb57a04db7cca068fed1c15badc064a302,
"zlib_inflate: Upgrade library code to a recent version" then that was
mainly a zlib_inflate change, not a zlib_deflate change.

But yes, I'd say that this patch might well have been the cause.

http://userweb.kernel.org/~akpm/zlib-backout.patch is a backout patch
against 2.6.21.  If you apply that to 2.6.21 does it make ppp work again?

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Stefan Wenk]

On Sunday 29 April 2007 23:20, Andrew Morton wrote:
> (switch to email - please retain all ccs)
>
> On Sun, 29 Apr 2007 13:01:25 -0700 bugme-daemon@bugzilla.kernel.org wrote:
> > http://bugzilla.kernel.org/show_bug.cgi?id=8405
> >
> >            Summary: pppd does stops compresion with "Lost compression
> > sync" Kernel Version: 2.6.18-2.6.21
> >             Status: NEW
> >           Severity: normal
> >              Owner: other_modules@kernel-bugs.osdl.org
> >          Submitter: stefan.wenk@gmx.at
> >
> >
> > Most recent kernel where this bug did *NOT* occur:2.6.17
> > Distribution: Fedora core 3
> > Hardware Environment:
> > Software Environment:
> > Problem Description:
> > I have the same problem as reported on
> > http://www.luga.at/mailing-lists/luga/2007/02/msg00032.html (in German).
> > When I connect to my ISP via an analogue serial modem my Linux Box sends
> > a PPP Compression Control Protocol Termination Request with  "Lost
> > compression sync" to the provider and then the provider dropps the link.
> > This does not happen with kernel
> > 2.6.17, but happens from kernel version 2.6.18 to 2.6.21 (not tested:
> > 2.6.19). If I put the nodeflate command line to the pppd then the link
> > remains stable. Steps to reproduce:
> > In order to find out what is happening I have set up a ppp connection via
> > a serial nullmodem to another old Linux box (kernel 2.2.14) and have
> > activated the kernel debug in the ppp_deflate.ko module. The "Lost
> > compression sync:" is reproducable in this configuration - the only
> > difference is that the link remains (without deflate compression).
> >
> > Here is the log vor /var/log/messages:
> >
> > Apr 29 16:53:34 linux kernel: PPP Deflate Compression module registered
> > Apr 29 16:53:47 linux pppd[9090]: pppd 2.4.4 started by root, uid 0
> > Apr 29 16:53:47 linux pppd[9090]: Using interface ppp0
> > Apr 29 16:53:47 linux pppd[9090]: Connect: ppp0 <--> /dev/pts/9
> > Apr 29 16:53:47 linux pppd[9090]: kernel does not support PPP filtering
> > Apr 29 16:53:47 linux pppd[9090]: Deflate (15) compression enabled
> > Apr 29 16:53:47 linux pppd[9090]: Cannot determine ethernet address for
> > proxy ARP Apr 29 16:53:47 linux pppd[9090]: local  IP address 192.168.3.2
> > Apr 29 16:53:47 linux pppd[9090]: remote IP address 192.168.3.1
> > Apr 29 16:54:03 linux kernel: z_decompress0: inflate returned -5 ()
> > Apr 29 16:54:03 linux pppd[9090]: PPPIOCGFLAGS flags: c030c0
> > Apr 29 16:54:03 linux pppd[9090]: Lost compression sync: disabling
> > compression
> >
> > I had a look at the kernel patch of 2.6.18 - the lib/zlib/zlib_inflate
> > was changed a lot and for me it looks to be the reason of the problem.
>
> If you're referring to 4f3865fb57a04db7cca068fed1c15badc064a302,
> "zlib_inflate: Upgrade library code to a recent version" then that was
> mainly a zlib_inflate change, not a zlib_deflate change.
>
> But yes, I'd say that this patch might well have been the cause.
>
> http://userweb.kernel.org/~akpm/zlib-backout.patch is a backout patch
> against 2.6.21.  If you apply that to 2.6.21 does it make ppp work again?

thanks for this backout patch. I have applied it to 2.6.21 and now pppd is 
working with deflate again.

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Richard Purdie]

On Mon, 2007-04-30 at 14:08 +0200, Stefan Wenk wrote:
> On Sunday 29 April 2007 23:20, Andrew Morton wrote:
> > (switch to email - please retain all ccs)
> >
> > On Sun, 29 Apr 2007 13:01:25 -0700 bugme-daemon@bugzilla.kernel.org wrote:
> > > http://bugzilla.kernel.org/show_bug.cgi?id=8405
> > >
> > > Here is the log vor /var/log/messages:
> > >
> > > Apr 29 16:53:34 linux kernel: PPP Deflate Compression module registered
> > > Apr 29 16:53:47 linux pppd[9090]: pppd 2.4.4 started by root, uid 0
> > > Apr 29 16:53:47 linux pppd[9090]: Using interface ppp0
> > > Apr 29 16:53:47 linux pppd[9090]: Connect: ppp0 <--> /dev/pts/9
> > > Apr 29 16:53:47 linux pppd[9090]: kernel does not support PPP filtering
> > > Apr 29 16:53:47 linux pppd[9090]: Deflate (15) compression enabled
> > > Apr 29 16:53:47 linux pppd[9090]: Cannot determine ethernet address for
> > > proxy ARP Apr 29 16:53:47 linux pppd[9090]: local  IP address 192.168.3.2
> > > Apr 29 16:53:47 linux pppd[9090]: remote IP address 192.168.3.1
> > > Apr 29 16:54:03 linux kernel: z_decompress0: inflate returned -5 ()
> > > Apr 29 16:54:03 linux pppd[9090]: PPPIOCGFLAGS flags: c030c0
> > > Apr 29 16:54:03 linux pppd[9090]: Lost compression sync: disabling
> > > compression
> > >
> > > I had a look at the kernel patch of 2.6.18 - the lib/zlib/zlib_inflate
> > > was changed a lot and for me it looks to be the reason of the problem.
> >
> > If you're referring to 4f3865fb57a04db7cca068fed1c15badc064a302,
> > "zlib_inflate: Upgrade library code to a recent version" then that was
> > mainly a zlib_inflate change, not a zlib_deflate change.
> >
> > But yes, I'd say that this patch might well have been the cause.
> >
> > http://userweb.kernel.org/~akpm/zlib-backout.patch is a backout patch
> > against 2.6.21.  If you apply that to 2.6.21 does it make ppp work again?
> 
> thanks for this backout patch. I have applied it to 2.6.21 and now pppd is 
> working with deflate again.

The key line of that log is 
"Apr 29 16:54:03 linux kernel: z_decompress0: inflate returned -5 ()"

linux/zlib.h says:

#define Z_BUF_ERROR    (-5)

so somehow we're triggering a buffer error...

Looking at zlib_inflate() in lib/zlib_inflate/inflate.c, it seems that
error only occurs if we had success (Z_OK) but no remaining input/output
space. I suspect you can just have ppp_deflate ignore that "error" code
and it might just work.

Can you try the following patch:

Index: linux-2.6.20/drivers/net/ppp_deflate.c
===================================================================
--- linux-2.6.20.orig/drivers/net/ppp_deflate.c	2007-02-04 18:44:54.000000000 +0000
+++ linux-2.6.20/drivers/net/ppp_deflate.c	2007-04-30 14:27:08.000000000 +0100
@@ -487,12 +487,16 @@ int z_decompress(void *arg, unsigned cha
 	 */
 	for (;;) {
 		r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
-		if (r != Z_OK) {
+		if ((r != Z_OK) && (r != Z_BUF_ERROR)) {
 			if (state->debug)
 				printk(KERN_DEBUG "z_decompress%d: inflate returned %d (%s)\n",
 				       state->unit, r, (state->strm.msg? state->strm.msg: ""));
 			return DECOMP_FATALERROR;
 		}
+		if (r == Z_BUF_ERROR) {
+			printk(KERN_DEBUG "z_decompress%d: Would have triggered an error as inflate returned %d (%s)\n",
+				       state->unit, r, (state->strm.msg? state->strm.msg: ""));
+		}
 		if (state->strm.avail_out != 0)
 			break;		/* all done */
 		if (decode_proto) {

This should continue but print some debug output when the problem
occurs.

Richard

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Stefan Wenk]

[-- Attachment #1: Type: text/plain, Size: 4481 bytes --]

On Monday 30 April 2007 15:31, Richard Purdie wrote:
> On Mon, 2007-04-30 at 14:08 +0200, Stefan Wenk wrote:
> > On Sunday 29 April 2007 23:20, Andrew Morton wrote:
> > > (switch to email - please retain all ccs)
> > >
> > > On Sun, 29 Apr 2007 13:01:25 -0700 bugme-daemon@bugzilla.kernel.org 
wrote:
> > > > http://bugzilla.kernel.org/show_bug.cgi?id=8405
> > > >
> > > > Here is the log vor /var/log/messages:
> > > >
> > > > Apr 29 16:53:34 linux kernel: PPP Deflate Compression module
> > > > registered Apr 29 16:53:47 linux pppd[9090]: pppd 2.4.4 started by
> > > > root, uid 0 Apr 29 16:53:47 linux pppd[9090]: Using interface ppp0
> > > > Apr 29 16:53:47 linux pppd[9090]: Connect: ppp0 <--> /dev/pts/9
> > > > Apr 29 16:53:47 linux pppd[9090]: kernel does not support PPP
> > > > filtering Apr 29 16:53:47 linux pppd[9090]: Deflate (15) compression
> > > > enabled Apr 29 16:53:47 linux pppd[9090]: Cannot determine ethernet
> > > > address for proxy ARP Apr 29 16:53:47 linux pppd[9090]: local  IP
> > > > address 192.168.3.2 Apr 29 16:53:47 linux pppd[9090]: remote IP
> > > > address 192.168.3.1 Apr 29 16:54:03 linux kernel: z_decompress0:
> > > > inflate returned -5 () Apr 29 16:54:03 linux pppd[9090]: PPPIOCGFLAGS
> > > > flags: c030c0 Apr 29 16:54:03 linux pppd[9090]: Lost compression
> > > > sync: disabling compression
> > > >
> > > > I had a look at the kernel patch of 2.6.18 - the
> > > > lib/zlib/zlib_inflate was changed a lot and for me it looks to be the
> > > > reason of the problem.
> > >
> > > If you're referring to 4f3865fb57a04db7cca068fed1c15badc064a302,
> > > "zlib_inflate: Upgrade library code to a recent version" then that was
> > > mainly a zlib_inflate change, not a zlib_deflate change.
> > >
> > > But yes, I'd say that this patch might well have been the cause.
> > >
> > > http://userweb.kernel.org/~akpm/zlib-backout.patch is a backout patch
> > > against 2.6.21.  If you apply that to 2.6.21 does it make ppp work
> > > again?
> >
> > thanks for this backout patch. I have applied it to 2.6.21 and now pppd
> > is working with deflate again.
>
> The key line of that log is
> "Apr 29 16:54:03 linux kernel: z_decompress0: inflate returned -5 ()"
>
> linux/zlib.h says:
>
> #define Z_BUF_ERROR    (-5)
>
> so somehow we're triggering a buffer error...
>
> Looking at zlib_inflate() in lib/zlib_inflate/inflate.c, it seems that
> error only occurs if we had success (Z_OK) but no remaining input/output
> space. I suspect you can just have ppp_deflate ignore that "error" code
> and it might just work.
>
> Can you try the following patch:
>
> Index: linux-2.6.20/drivers/net/ppp_deflate.c
> ===================================================================
> --- linux-2.6.20.orig/drivers/net/ppp_deflate.c 2007-02-04
> 18:44:54.000000000 +0000 +++
> linux-2.6.20/drivers/net/ppp_deflate.c 2007-04-30 14:27:08.000000000 +0100
> @@ -487,12 +487,16 @@ int z_decompress(void *arg, unsigned cha
>    */
>   for (;;) {
>    r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
> -  if (r != Z_OK) {
> +  if ((r != Z_OK) && (r != Z_BUF_ERROR)) {
>     if (state->debug)
>      printk(KERN_DEBUG "z_decompress%d: inflate returned %d (%s)\n",
>             state->unit, r, (state->strm.msg? state->strm.msg: ""));
>     return DECOMP_FATALERROR;
>    }
> +  if (r == Z_BUF_ERROR) {
> +   printk(KERN_DEBUG "z_decompress%d: Would have triggered an error as
> inflate returned %d (%s)\n", +           state->unit, r, (state->strm.msg?
> state->strm.msg: "")); +  }
>    if (state->strm.avail_out != 0)
>     break;  /* all done */
>    if (decode_proto) {
>
> This should continue but print some debug output when the problem
> occurs.
>
> Richard

Actually I have tried that before writing this report - it does not work. 
The behaviour is not deterministic. When I'm accessing a web-server via the 
null-modem cable and I see with this modification the following on the kernel 
log:

z_decompress0: Would have triggered an error as inflate returned -5 ()
...... repeated ....
z_decompress0: Would have triggered an error as inflate returned -5 ()
z_incomp0: inflateIncomp returned -3 ()
z_decompress0: Would have triggered an error as inflate returned -5 ()

What is more interesting is that the pppd server log is logging errors.
There are LCP EchoReq and EchoRep. Later a LCP ProtoRej messages occurs and 
then the connection is broken. I have attached a pppdump file of the client 
side if it helps. This file can be read e.g. by wireshark.

[-- Attachment #2: selfhtml.pppdump --]
[-- Type: application/octet-stream, Size: 99430 bytes --]

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Stefan Wenk]

On Monday 30 April 2007 21:12, Stefan Wenk wrote:
> On Monday 30 April 2007 15:31, Richard Purdie wrote:
> > On Mon, 2007-04-30 at 14:08 +0200, Stefan Wenk wrote:
> > > On Sunday 29 April 2007 23:20, Andrew Morton wrote:
> > > > (switch to email - please retain all ccs)
> > > >
> > > > On Sun, 29 Apr 2007 13:01:25 -0700 bugme-daemon@bugzilla.kernel.org
>
> wrote:
> > > > > http://bugzilla.kernel.org/show_bug.cgi?id=8405
> > > > >
> > > > > Here is the log vor /var/log/messages:
> > > > >
> > > > > Apr 29 16:53:34 linux kernel: PPP Deflate Compression module
> > > > > registered Apr 29 16:53:47 linux pppd[9090]: pppd 2.4.4 started by
> > > > > root, uid 0 Apr 29 16:53:47 linux pppd[9090]: Using interface ppp0
> > > > > Apr 29 16:53:47 linux pppd[9090]: Connect: ppp0 <--> /dev/pts/9
> > > > > Apr 29 16:53:47 linux pppd[9090]: kernel does not support PPP
> > > > > filtering Apr 29 16:53:47 linux pppd[9090]: Deflate (15)
> > > > > compression enabled Apr 29 16:53:47 linux pppd[9090]: Cannot
> > > > > determine ethernet address for proxy ARP Apr 29 16:53:47 linux
> > > > > pppd[9090]: local  IP address 192.168.3.2 Apr 29 16:53:47 linux
> > > > > pppd[9090]: remote IP address 192.168.3.1 Apr 29 16:54:03 linux
> > > > > kernel: z_decompress0: inflate returned -5 () Apr 29 16:54:03 linux
> > > > > pppd[9090]: PPPIOCGFLAGS flags: c030c0 Apr 29 16:54:03 linux
> > > > > pppd[9090]: Lost compression sync: disabling compression
> > > > >
> > > > > I had a look at the kernel patch of 2.6.18 - the
> > > > > lib/zlib/zlib_inflate was changed a lot and for me it looks to be
> > > > > the reason of the problem.
> > > >
> > > > If you're referring to 4f3865fb57a04db7cca068fed1c15badc064a302,
> > > > "zlib_inflate: Upgrade library code to a recent version" then that
> > > > was mainly a zlib_inflate change, not a zlib_deflate change.
> > > >
> > > > But yes, I'd say that this patch might well have been the cause.
> > > >
> > > > http://userweb.kernel.org/~akpm/zlib-backout.patch is a backout patch
> > > > against 2.6.21.  If you apply that to 2.6.21 does it make ppp work
> > > > again?
> > >
> > > thanks for this backout patch. I have applied it to 2.6.21 and now pppd
> > > is working with deflate again.
> >
> > The key line of that log is
> > "Apr 29 16:54:03 linux kernel: z_decompress0: inflate returned -5 ()"
> >
> > linux/zlib.h says:
> >
> > #define Z_BUF_ERROR    (-5)
> >
> > so somehow we're triggering a buffer error...
> >
> > Looking at zlib_inflate() in lib/zlib_inflate/inflate.c, it seems that
> > error only occurs if we had success (Z_OK) but no remaining input/output
> > space. I suspect you can just have ppp_deflate ignore that "error" code
> > and it might just work.
> >
> > Can you try the following patch:
> >
> > Index: linux-2.6.20/drivers/net/ppp_deflate.c
> > ===================================================================
> > --- linux-2.6.20.orig/drivers/net/ppp_deflate.c 2007-02-04
> > 18:44:54.000000000 +0000 +++
> > linux-2.6.20/drivers/net/ppp_deflate.c 2007-04-30 14:27:08.000000000
> > +0100 @@ -487,12 +487,16 @@ int z_decompress(void *arg, unsigned cha
> >    */
> >   for (;;) {
> >    r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
> > -  if (r != Z_OK) {
> > +  if ((r != Z_OK) && (r != Z_BUF_ERROR)) {
> >     if (state->debug)
> >      printk(KERN_DEBUG "z_decompress%d: inflate returned %d (%s)\n",
> >             state->unit, r, (state->strm.msg? state->strm.msg: ""));
> >     return DECOMP_FATALERROR;
> >    }
> > +  if (r == Z_BUF_ERROR) {
> > +   printk(KERN_DEBUG "z_decompress%d: Would have triggered an error as
> > inflate returned %d (%s)\n", +           state->unit, r,
> > (state->strm.msg? state->strm.msg: "")); +  }
> >    if (state->strm.avail_out != 0)
> >     break;  /* all done */
> >    if (decode_proto) {
> >
> > This should continue but print some debug output when the problem
> > occurs.
> >
> > Richard
>
> Actually I have tried that before writing this report - it does not work.
> The behaviour is not deterministic. When I'm accessing a web-server via the
> null-modem cable and I see with this modification the following on the
> kernel log:
>
> z_decompress0: Would have triggered an error as inflate returned -5 ()
> ...... repeated ....
> z_decompress0: Would have triggered an error as inflate returned -5 ()
> z_incomp0: inflateIncomp returned -3 ()
> z_decompress0: Would have triggered an error as inflate returned -5 ()
>
> What is more interesting is that the pppd server log is logging errors.
> There are LCP EchoReq and EchoRep. Later a LCP ProtoRej messages occurs and
> then the connection is broken. I have attached a pppdump file of the client
> side if it helps. This file can be read e.g. by wireshark.

I should have mentioned that I have made some other modifications in order to 
see the kernel logging. This was because I could not find the documentation 
how to turn debugging on for ppp_deflate and because I'm only seeing printk 
of type KERN_ERR and not those with KERN_DEBUG. So I might be missing some 
additional KERN_DEBUG loggings. If somebody can point me to the documentation 
how to get KERN_DEBUG to the log file I can make the test again.

Here is the full diff 

--- ppp_deflate.c.orig  2007-04-23 20:47:08.000000000 +0200
+++ ppp_deflate.c       2007-04-30 19:38:19.000000000 +0200
@@ -174,7 +174,7 @@ static int z_comp_init(void *arg, unsign

        state->seqno = 0;
        state->unit  = unit;
-       state->debug = debug;
+       state->debug = 1;

        zlib_deflateReset(&state->strm);

@@ -393,7 +393,7 @@ static int z_decomp_init(void *arg, unsi

        state->seqno = 0;
        state->unit  = unit;
-       state->debug = debug;
+       state->debug = 1;
        state->mru   = mru;

        zlib_inflateReset(&state->strm);
@@ -487,12 +487,18 @@ int z_decompress(void *arg, unsigned cha
         */
        for (;;) {
                r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
-               if (r != Z_OK) {
+//             if (r != Z_OK) {
+                if ((r != Z_OK) && (r != Z_BUF_ERROR)) {
                        if (state->debug)
-                               printk(KERN_DEBUG "z_decompress%d: inflate 
returned %d (%s)\n",
+                               printk(KERN_ERR "z_decompress%d: inflate 
returned %d (%s)\n",
                                       state->unit, r, (state->strm.msg? 
state->strm.msg: ""));
                        return DECOMP_FATALERROR;
                }
+                if (r == Z_BUF_ERROR) {
+                             printk(KERN_ERR "z_decompress%d: Would have 
triggered an error as inflate returned %d (%s)\n",
+                             state->unit, r, (state->strm.msg? 
state->strm.msg: ""));
+                }

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Andrew Morton]

On Tue, 1 May 2007 05:20:10 +0200 Stefan Wenk <stefan.wenk@gmx.at> wrote:

> > What is more interesting is that the pppd server log is logging errors.
> > There are LCP EchoReq and EchoRep. Later a LCP ProtoRej messages occurs and
> > then the connection is broken. I have attached a pppdump file of the client
> > side if it helps. This file can be read e.g. by wireshark.
> 
> I should have mentioned that I have made some other modifications in order to 
> see the kernel logging. This was because I could not find the documentation 
> how to turn debugging on for ppp_deflate and because I'm only seeing printk 
> of type KERN_ERR and not those with KERN_DEBUG. So I might be missing some 
> additional KERN_DEBUG loggings. If somebody can point me to the documentation 
> how to get KERN_DEBUG to the log file I can make the test again.

>From the commend line: `dmesg -n 8'.

The really big fix is to boot with the ignore_loglevel boot option.  This will
turn on all messages and will defeat any userspace attempt to turn the
loglevel down.

> Here is the full diff 

Thanks for persisting with this.  The problem is rather serious.

> --- ppp_deflate.c.orig  2007-04-23 20:47:08.000000000 +0200
> +++ ppp_deflate.c       2007-04-30 19:38:19.000000000 +0200
> @@ -174,7 +174,7 @@ static int z_comp_init(void *arg, unsign
> 
>         state->seqno = 0;
>         state->unit  = unit;
> -       state->debug = debug;
> +       state->debug = 1;
> 
>         zlib_deflateReset(&state->strm);
> 
> @@ -393,7 +393,7 @@ static int z_decomp_init(void *arg, unsi
> 
>         state->seqno = 0;
>         state->unit  = unit;
> -       state->debug = debug;
> +       state->debug = 1;
>         state->mru   = mru;
> 
>         zlib_inflateReset(&state->strm);
> @@ -487,12 +487,18 @@ int z_decompress(void *arg, unsigned cha
>          */
>         for (;;) {
>                 r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
> -               if (r != Z_OK) {
> +//             if (r != Z_OK) {
> +                if ((r != Z_OK) && (r != Z_BUF_ERROR)) {
>                         if (state->debug)
> -                               printk(KERN_DEBUG "z_decompress%d: inflate 
> returned %d (%s)\n",
> +                               printk(KERN_ERR "z_decompress%d: inflate 
> returned %d (%s)\n",
>                                        state->unit, r, (state->strm.msg? 
> state->strm.msg: ""));
>                         return DECOMP_FATALERROR;
>                 }
> +                if (r == Z_BUF_ERROR) {
> +                             printk(KERN_ERR "z_decompress%d: Would have 
> triggered an error as inflate returned %d (%s)\n",
> +                             state->unit, r, (state->strm.msg? 
> state->strm.msg: ""));
> +                }
> 

(that was wordwrapped).

What does it do?

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Stefan Wenk]

> >From the commend line: `dmesg -n 8'.
>
> The really big fix is to boot with the ignore_loglevel boot option.  This
> will turn on all messages and will defeat any userspace attempt to turn the
> loglevel down.
Thanks. With this command I see also the KERN_DEBUG printks now.
>
> > Here is the full diff
>
> Thanks for persisting with this.  The problem is rather serious.
If you have instructions how to proceed I'm looking forward to help solving 
it. I guess reverting the zlib modification in the Linux main line is no 
option. What I'm wondering is that this issue hasn't been detected earlier. 
Looks as nobody is using analogue modems and nullmodem cables any more.
>
> > --- ppp_deflate.c.orig  2007-04-23 20:47:08.000000000 +0200
> > +++ ppp_deflate.c       2007-04-30 19:38:19.000000000 +0200
> > @@ -174,7 +174,7 @@ static int z_comp_init(void *arg, unsign
> >
> >         state->seqno = 0;
> >         state->unit  = unit;
> > -       state->debug = debug;
> > +       state->debug = 1;
> >
> >         zlib_deflateReset(&state->strm);
> >
> > @@ -393,7 +393,7 @@ static int z_decomp_init(void *arg, unsi
> >
> >         state->seqno = 0;
> >         state->unit  = unit;
> > -       state->debug = debug;
> > +       state->debug = 1;
> >         state->mru   = mru;
> >
> >         zlib_inflateReset(&state->strm);
> > @@ -487,12 +487,18 @@ int z_decompress(void *arg, unsigned cha
> >          */
> >         for (;;) {
> >                 r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
> > -               if (r != Z_OK) {
> > +//             if (r != Z_OK) {
> > +                if ((r != Z_OK) && (r != Z_BUF_ERROR)) {
> >                         if (state->debug)
> > -                               printk(KERN_DEBUG "z_decompress%d:
> > inflate returned %d (%s)\n",
> > +                               printk(KERN_ERR "z_decompress%d: inflate
> > returned %d (%s)\n",
> >                                        state->unit, r, (state->strm.msg?
> > state->strm.msg: ""));
> >                         return DECOMP_FATALERROR;
> >                 }
> > +                if (r == Z_BUF_ERROR) {
> > +                             printk(KERN_ERR "z_decompress%d: Would have
> > triggered an error as inflate returned %d (%s)\n",
> > +                             state->unit, r, (state->strm.msg?
> > state->strm.msg: ""));
> > +                }
>
> (that was wordwrapped).
Sorry. I should have made an attachment.
>
> What does it do?
It was just for debugging. Forget it. Now I have changed these modifications 
back, and I do not see more debug information except those below:

z_decompress0: Would have triggered an error as inflate returned -5 ()
z_decompress0: Would have triggered an error as inflate returned -5 ()
z_decompress0: Would have triggered an error as inflate returned -5 ()
..
As there are no debug logs in inflate.c I can't provide more information by 
now.

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Richard Purdie]

On Tue, 2007-05-01 at 09:27 +0200, Stefan Wenk wrote:
> Now I have changed these modifications 
> back, and I do not see more debug information except those below:
> 
> z_decompress0: Would have triggered an error as inflate returned -5 ()
> z_decompress0: Would have triggered an error as inflate returned -5 ()
> z_decompress0: Would have triggered an error as inflate returned -5 ()
> ..
> As there are no debug logs in inflate.c I can't provide more information by 
> now.

I had a look at that trace you sent, the echo and replys were normal but
obviously something is going wrong and it tries to negotiate turning off
the compression...

Having looked at the code a bit further, I have a theory that it was
impossible to reach the zlib_inflateSyncPacket call ppp deflate needs.
The patch below fixes that and also adds some debugging so if that isn't
the problem, we might get some further clues as to what the problem
is...

Thanks for the patience :)

Richard

Index: linux/drivers/net/ppp_deflate.c
===================================================================
--- linux.orig/drivers/net/ppp_deflate.c	2007-01-18 00:52:50.000000000 +0000
+++ linux/drivers/net/ppp_deflate.c	2007-05-01 22:21:27.000000000 +0100
@@ -488,6 +488,13 @@ int z_decompress(void *arg, unsigned cha
 	for (;;) {
 		r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
 		if (r != Z_OK) {
+			printk(KERN_ERR "z_decompress%d: inflate returned %d (%s)"
+				",av in %d, av out %d, t in %ld, t out %ld, dp %d,"
+				" of %d, is %d, os %d\n",
+				state->unit, r, (state->strm.msg? state->strm.msg: ""),
+				state->strm.avail_in, state->strm.avail_out,
+				state->strm.total_in, state->strm.total_out,
+				decode_proto, overflow, isize, osize);
 			if (state->debug)
 				printk(KERN_DEBUG "z_decompress%d: inflate returned %d (%s)\n",
 				       state->unit, r, (state->strm.msg? state->strm.msg: ""));
Index: linux/lib/zlib_inflate/inflate.c
===================================================================
--- linux.orig/lib/zlib_inflate/inflate.c	2007-01-18 00:53:08.000000000 +0000
+++ linux/lib/zlib_inflate/inflate.c	2007-05-01 22:03:53.000000000 +0100
@@ -743,12 +743,14 @@ int zlib_inflate(z_streamp strm, int flu
 
     strm->data_type = state->bits + (state->last ? 64 : 0) +
                       (state->mode == TYPE ? 128 : 0);
-    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
-        ret = Z_BUF_ERROR;
 
     if (flush == Z_PACKET_FLUSH && ret == Z_OK &&
             (strm->avail_out != 0 || strm->avail_in == 0))
 		return zlib_inflateSyncPacket(strm);
+
+    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
+        ret = Z_BUF_ERROR;
+
     return ret;
 }
 

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Stefan Wenk]

[-- Attachment #1: Type: text/plain, Size: 3358 bytes --]

> Having looked at the code a bit further, I have a theory that it was
> impossible to reach the zlib_inflateSyncPacket call ppp deflate needs.
> The patch below fixes that and also adds some debugging so if that isn't
> the problem, we might get some further clues as to what the problem
> is...
>
> Thanks for the patience :)
>
> Richard
>
> Index: linux/drivers/net/ppp_deflate.c
> ===================================================================
> --- linux.orig/drivers/net/ppp_deflate.c 2007-01-18 00:52:50.000000000
> +0000 +++ linux/drivers/net/ppp_deflate.c 2007-05-01 22:21:27.000000000
> +0100 @@ -488,6 +488,13 @@ int z_decompress(void *arg, unsigned cha
>   for (;;) {
>    r = zlib_inflate(&state->strm, Z_PACKET_FLUSH);
>    if (r != Z_OK) {
> +   printk(KERN_ERR "z_decompress%d: inflate returned %d (%s)"
> +    ",av in %d, av out %d, t in %ld, t out %ld, dp %d,"
> +    " of %d, is %d, os %d\n",
> +    state->unit, r, (state->strm.msg? state->strm.msg: ""),
> +    state->strm.avail_in, state->strm.avail_out,
> +    state->strm.total_in, state->strm.total_out,
> +    decode_proto, overflow, isize, osize);
>     if (state->debug)
>      printk(KERN_DEBUG "z_decompress%d: inflate returned %d (%s)\n",
>             state->unit, r, (state->strm.msg? state->strm.msg: ""));
> Index: linux/lib/zlib_inflate/inflate.c
> ===================================================================
> --- linux.orig/lib/zlib_inflate/inflate.c 2007-01-18 00:53:08.000000000
> +0000 +++ linux/lib/zlib_inflate/inflate.c 2007-05-01 22:03:53.000000000
> +0100 @@ -743,12 +743,14 @@ int zlib_inflate(z_streamp strm, int flu
>
>      strm->data_type = state->bits + (state->last ? 64 : 0) +
>                        (state->mode == TYPE ? 128 : 0);
> -    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
> -        ret = Z_BUF_ERROR;
>
>      if (flush == Z_PACKET_FLUSH && ret == Z_OK &&
>              (strm->avail_out != 0 || strm->avail_in == 0))
>    return zlib_inflateSyncPacket(strm);
> +
> +    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
> +        ret = Z_BUF_ERROR;
> +
>      return ret;
>  }

The situation now is similar as without any modifications. Instead of -5 
(Z_BUF_ERROR)
we get back -3 (Z_DATA_ERROR) from zlib_inflate. Here is the kernel log

kernel: PPP generic driver version 2.4.2
pppd[6101]: pppd 2.4.4 started by root, uid 0
pppd[6101]: Using interface ppp0
pppd[6101]: Connect: ppp0 <--> /dev/pts/8
pppd[6101]: kernel does not support PPP filtering
kernel: PPP BSD Compression module registered
kernel: PPP Deflate Compression module registered
pppd[6101]: Deflate (15) compression enabled
pppd[6101]: Cannot determine ethernet address for proxy ARP
pppd[6101]: local  IP address 192.168.3.2
pppd[6101]: remote IP address 192.168.3.1
kernel: z_decompress0: inflate returned -3 (),av in 0, av out 1, t in 1520, t 
out 3070, dp 0, of 1, is 644, os 1504
kernel: z_decompress0: inflate returned -3 ()
pppd[6101]: Lost compression sync: disabling compression
pppd[6101]: Terminating on signal 2
pppd[6101]: Child process pppd (charshunt) (pid 6131) terminated with signal 2
pppd[6101]: Modem hangup
pppd[6101]: Connect time 0.2 minutes.
pppd[6101]: Sent 2969 bytes, received 2774 bytes.
pppd[6101]: Connection terminated.
pppd[6101]: Exit.

Attached you find the corresponding pppdump file.

[-- Attachment #2: selfhtml2.ppdump --]
[-- Type: application/octet-stream, Size: 5044 bytes --]

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Richard Purdie]

On Wed, 2007-05-02 at 18:59 +0200, Stefan Wenk wrote:
> The situation now is similar as without any modifications. Instead of -5 
> (Z_BUF_ERROR)
> we get back -3 (Z_DATA_ERROR) from zlib_inflate. Here is the kernel log
> 
> kernel: PPP generic driver version 2.4.2
> pppd[6101]: pppd 2.4.4 started by root, uid 0
> pppd[6101]: Using interface ppp0
> pppd[6101]: Connect: ppp0 <--> /dev/pts/8
> pppd[6101]: kernel does not support PPP filtering
> kernel: PPP BSD Compression module registered
> kernel: PPP Deflate Compression module registered
> pppd[6101]: Deflate (15) compression enabled
> pppd[6101]: Cannot determine ethernet address for proxy ARP
> pppd[6101]: local  IP address 192.168.3.2
> pppd[6101]: remote IP address 192.168.3.1
> kernel: z_decompress0: inflate returned -3 (),av in 0, av out 1, t in 1520, t 
> out 3070, dp 0, of 1, is 644, os 1504
> kernel: z_decompress0: inflate returned -3 ()
> pppd[6101]: Lost compression sync: disabling compression
> pppd[6101]: Terminating on signal 2
> pppd[6101]: Child process pppd (charshunt) (pid 6131) terminated with signal 2
> pppd[6101]: Modem hangup
> pppd[6101]: Connect time 0.2 minutes.
> pppd[6101]: Sent 2969 bytes, received 2774 bytes.
> pppd[6101]: Connection terminated.
> pppd[6101]: Exit.
> 
> Attached you find the corresponding pppdump file.

Thanks, the interesting bit is that overflow=1. The Z_DATA_ERROR is
probably coming from zlib_inflateSyncPacket() suggesting a logic error.

I managed to find a null modem cable, create this setup and occasionally
reproduce the problem. I think the change I suggested was half way there
but there is another problem. Could you try this patch and see if it
fixes your errors? 

I haven't seen the problem occur here on my box with the patch below
applied. Having said that, I was testing against a box running 2.6.11.2
and I did see similar looking compression errors appearing on that just
before I was about to send this after stressing the link for an hour.
This could mean there is some more subtle problem (not related to the
inflate patch). It is sending Reset requests rather than Term Requests
though so perhaps its some other problem. Lets see what you find with
the patch below...

Cheers,

Richard

Index: linux-2.6.20-rc4/lib/zlib_inflate/inflate.c
===================================================================
--- linux-2.6.20-rc4.orig/lib/zlib_inflate/inflate.c
+++ linux-2.6.20-rc4/lib/zlib_inflate/inflate.c
@@ -743,12 +745,14 @@ int zlib_inflate(z_streamp strm, int flu
 
     strm->data_type = state->bits + (state->last ? 64 : 0) +
                       (state->mode == TYPE ? 128 : 0);
-    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
-        ret = Z_BUF_ERROR;
 
     if (flush == Z_PACKET_FLUSH && ret == Z_OK &&
-            (strm->avail_out != 0 || strm->avail_in == 0))
+            strm->avail_out != 0 && strm->avail_in == 0)
 		return zlib_inflateSyncPacket(strm);
+
+    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
+        ret = Z_BUF_ERROR;
+
     return ret;
 }
 

Re: [Bugme-new] [Bug 8405] New: pppd does stops compresion with "Lost compression sync"

[Stefan Wenk]

On Thursday 03 May 2007 02:23, Richard Purdie wrote:
> On Wed, 2007-05-02 at 18:59 +0200, Stefan Wenk wrote:
> > The situation now is similar as without any modifications. Instead of -5
> > (Z_BUF_ERROR)
> > we get back -3 (Z_DATA_ERROR) from zlib_inflate. Here is the kernel log
> >
> > kernel: PPP generic driver version 2.4.2
> > pppd[6101]: pppd 2.4.4 started by root, uid 0
> > pppd[6101]: Using interface ppp0
> > pppd[6101]: Connect: ppp0 <--> /dev/pts/8
> > pppd[6101]: kernel does not support PPP filtering
> > kernel: PPP BSD Compression module registered
> > kernel: PPP Deflate Compression module registered
> > pppd[6101]: Deflate (15) compression enabled
> > pppd[6101]: Cannot determine ethernet address for proxy ARP
> > pppd[6101]: local  IP address 192.168.3.2
> > pppd[6101]: remote IP address 192.168.3.1
> > kernel: z_decompress0: inflate returned -3 (),av in 0, av out 1, t in
> > 1520, t out 3070, dp 0, of 1, is 644, os 1504
> > kernel: z_decompress0: inflate returned -3 ()
> > pppd[6101]: Lost compression sync: disabling compression
> > pppd[6101]: Terminating on signal 2
> > pppd[6101]: Child process pppd (charshunt) (pid 6131) terminated with
> > signal 2 pppd[6101]: Modem hangup
> > pppd[6101]: Connect time 0.2 minutes.
> > pppd[6101]: Sent 2969 bytes, received 2774 bytes.
> > pppd[6101]: Connection terminated.
> > pppd[6101]: Exit.
> >
> > Attached you find the corresponding pppdump file.
>
> Thanks, the interesting bit is that overflow=1. The Z_DATA_ERROR is
> probably coming from zlib_inflateSyncPacket() suggesting a logic error.
>
> I managed to find a null modem cable, create this setup and occasionally
> reproduce the problem. I think the change I suggested was half way there
> but there is another problem. Could you try this patch and see if it
> fixes your errors?
>
> I haven't seen the problem occur here on my box with the patch below
> applied. Having said that, I was testing against a box running 2.6.11.2
> and I did see similar looking compression errors appearing on that just
> before I was about to send this after stressing the link for an hour.
> This could mean there is some more subtle problem (not related to the
> inflate patch). It is sending Reset requests rather than Term Requests
> though so perhaps its some other problem. Lets see what you find with
> the patch below...
>
> Cheers,
>
> Richard
>
> Index: linux-2.6.20-rc4/lib/zlib_inflate/inflate.c
> ===================================================================
> --- linux-2.6.20-rc4.orig/lib/zlib_inflate/inflate.c
> +++ linux-2.6.20-rc4/lib/zlib_inflate/inflate.c
> @@ -743,12 +745,14 @@ int zlib_inflate(z_streamp strm, int flu
>
>      strm->data_type = state->bits + (state->last ? 64 : 0) +
>                        (state->mode == TYPE ? 128 : 0);
> -    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
> -        ret = Z_BUF_ERROR;
>
>      if (flush == Z_PACKET_FLUSH && ret == Z_OK &&
> -            (strm->avail_out != 0 || strm->avail_in == 0))
> +            strm->avail_out != 0 && strm->avail_in == 0)
>    return zlib_inflateSyncPacket(strm);
> +
> +    if (((in == 0 && out == 0) || flush == Z_FINISH) && ret == Z_OK)
> +        ret = Z_BUF_ERROR;
> +
>      return ret;
>  }
With this modification the reported problem with the lost compression sync is 
fixed indeed. Thank you! I have tried to stress the nullmodem link and on 
application level everthing looks fine now. But I do also sometimes see CCP 
Reset Requests which are sent by the box with the 2.6.21 kernel.  This 
problem seems to be fixed on the TCP layer, so the applications do not 
recognise. I can't tell is this the ordinary behaviour as I have never looked 
at the PPP level in such detail before. I do agree with you that if this is a 
problem it does not look to be related with the issue which you fixed now.

Ciao Stefan