Bug 33102

(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

On Mon, 11 Apr 2011 22:12:41 GMT
bugzilla-daemon@bugzilla.kernel.org wrote:

> https://bugzilla.kernel.org/show_bug.cgi?id=33102
> 
>            Summary: File's copied from client->linux server only copy 1st
>                     64K data;rest is lost
>            Product: Networking
>            Version: 2.5
>     Kernel Version: 2.6.38.2
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: blocking
>           Priority: P1
>          Component: IPV4
>         AssignedTo: shemminger@linux-foundation.org
>         ReportedBy: lkml@tlinx.org
>         Regression: Yes

Seems to be a 2.6.37->2.6.38 regression.

> 
> Created an attachment (id=54112)
>  --> (https://bugzilla.kernel.org/attachment.cgi?id=54112)
> config file
> 
> I've run into a problem copying a 3.6M file from a Win7 client to
> the linux server via cifs.
> 
> 
> Under 2.6.38.2, it only copies the first 64K (exactly) and the
> client gets a write error.
> 
> Using wireshark, in the success case, after the client sends the first
> 64K, the server response with 4 acks  each advertising a Window
> size of ~48K, followed by an SMB packet acknowledging the first 64K, w/info:
>   "WRITE AndX Request, 65536 bytes".
> 
> In the fail case, the server responds with 4 acks, but in each of the
> 4 ACKS, it's advertising strange window sizes of 881, 1161, 1441 1721
> and then responds with a faulty SMB packet w/info:
>   "[TCP Retransmission] Trans2 Response<unknown>"
>  Under the Trans2 section it says:
> 
>   Subcommand: <Unknown> since request packet wasn't seen.
> 
> 
> ----
> 
> I originally upgraded from 2.6.35.7 -> 2.6.38.2 and encountered this
> prob, so successively tried the 26.35.7 config w/2.6.36, 37, 38 and finally
> 38.1 -- they all work.
> 
> The same config on 2.6.38.2 fails as described above.
> 
> 
> Config attached.
>

Andrew Morton wrote:
> (switched to email.  Please respond via emailed reply-to-all, not via the
> bugzilla web interface).
>
> On Mon, 11 Apr 2011 22:12:41 GMT
> bugzilla-daemon@bugzilla.kernel.org wrote:
>
>   
>> https://bugzilla.kernel.org/show_bug.cgi?id=33102
>>
>>            Summary: File's copied from client->linux server only copy 1st
>>                     64K data;rest is lost
>>            Product: Networking
>>            Version: 2.5
>>     Kernel Version: 2.6.38.2
>>           Platform: All
>>         OS/Version: Linux
>>               Tree: Mainline
>>             Status: NEW
>>           Severity: blocking
>>           Priority: P1
>>          Component: IPV4
>>         AssignedTo: shemminger@linux-foundation.org
>>         ReportedBy: lkml@tlinx.org
>>         Regression: Yes
>>     
>
> Seems to be a 2.6.37->2.6.38 regression.
>
> ----------

Not exactly -- Please note -- I tried both 2.6.38(.0) and 2.6.38.1.

They both work.

Interesting - I didn't see obvious changes to network stack in 2.6.38.2  at least at http://www.kernel.org/pub/linux/kernel/v2.6/ChangeLog-2.6.38.2

any chance that we could get a wireshark trace of the failure?

https://wiki.samba.org/index.php/Capture_Packets

gives instructions.

Reply-To: smfrench@gmail.com

On Mon, Apr 11, 2011 at 5:41 PM, Linda Walsh <lkml@tlinx.org> wrote:
>
> Andrew Morton wrote:
>>
>> (switched to email.  Please respond via emailed reply-to-all, not via the
>> bugzilla web interface).
>>
>> On Mon, 11 Apr 2011 22:12:41 GMT
>> bugzilla-daemon@bugzilla.kernel.org wrote:
>>>
>>> https://bugzilla.kernel.org/show_bug.cgi?id=33102
>>>
>>>           Summary: File's copied from client->linux server only copy 1st
>>>                    64K data;rest is lost
>>>           Product: Networking
>>>           Version: 2.5
>>>    Kernel Version: 2.6.38.2
>>>          Platform: All
>>>        OS/Version: Linux
>>>              Tree: Mainline
>>>            Status: NEW
>>>          Severity: blocking
>>>          Priority: P1
>>>         Component: IPV4
>>>        AssignedTo: shemminger@linux-foundation.org
>>>        ReportedBy: lkml@tlinx.org
>>>        Regression: Yes
>>>
>>
>> Seems to be a 2.6.37->2.6.38 regression.
>>
>> ----------
>
> Not exactly -- Please note -- I tried both 2.6.38(.0) and 2.6.38.1.
>
> They both work.

Any chance that we could get a wireshark trace of the failure?

https://wiki.samba.org/index.php/Capture_Packets

gives instructions.   There may also be useful information on
network stack failures returned in the samba log
(often named smbd.log).

Created attachment 54122 [details]
fail case for 2.6.38.2

Already had a dump from my earlier efforts to look @ problem.

First signs, I could see of problem, were @ packet @185, where the Win size was way below normal.  In a parallel working example, all of the Win sizes in those Acks were about 48K each.

After #185, there are few more TCP ACK's, then the first SMB packet following them @ #194, is where things look really wrong.  'Trans2<unknown>'...hasn't been seen...

BTW, if you want to see a parallel working case, it's not too difficult for me to regen it.  I'm currently running 2.6.38.1 and would use it to gen the comparison.

Created attachment 54132 [details]
working case of same file copy (w/2.6.38.1)

Here's the same trace, but the working case w/2.6.38.1.

The first ack of the file copy starts @ packet #186.

You can see what I believe is the corresponding SMB 'success response (corresponding to the one mentioned in the failure trace) @#190.  As soon as
that comes back from the Server, the client sends an additional 60K+ (62774) -- something that doesn't happen in the failure case.

The trace does look like there is a TCP problem (the retransmissions are also suspicious), but I also am curious where the WriteX is (I didn't see it in the trace) - perhaps it never makes it to the server (where presumably the wireshark trace was taken)?

Interestingly WriteX is the first large frame (the readdir responses were small) ~60K+ rather than 1K or less so it would be logical for a network problem to start with the first large frame.

In thinking about this trace, the number of QueryFileInfos and various frames that are probably not related to the failure that clutter the trace (presumably due to Windows Explorer) - if the failure is related to the first large frame sent on the network (SMB WriteX), it may be easier to reproduce this with a simple mount from cifs.ko (Linux cifs client) rather than from Windows 7 (where lots of metadata related queryfileinfo etc. get in the way of debugging).  Although the Linux cifs client uses 56K writes (rather than ~60K writes, as Windows uses) - the trace of the network traffic should be much smaller and easier to read.

About 63 patches between 2.6.38.1 and 2.6.38.2 right?  Could simply bisect until the problem patch is found.

The trace was taken on the client, as the server is GUI-less.  I've run wireshark on the server, but when I do, I display it on a client machine, which might cause interference (even though I filter out 'X' traffic and a few other ports to reduce potential clutter).

Filter that I ran during this trace:

    "not port 1138 and not port 6000 and not port 22 and not port 993 and not 9091 and not 8080".


Much of the SMB clutter during the failure conversation can be filtered out by using the following as a display filter in wireshark:

    !tcp ||  !smb || smb.fid!=0x1873 

The only open 'Explorer' process was the desktop.  I have the server setup to run as a domain server, so that may have been responsible for the extra 4 packets of clutter/second, though I don't **remember** (it's been a while since I've perused an XP trace) those packets being there on WinXP, so it might be something specific to Win7.

It got awfully quiet on this.  I take it bisecting isn't that easy?

I tried to find some place where the patches are even listed, but the closest thing I found was a list of the git summary links:
   http://git.kernel.org/?p=linux/kernel/git/stable/linux-2.6.38.y.git

From there I can look at diffs, for those by clicking on commitdiff, but
it's not a downloadable for a patch file and there certainly aren't 66 patches there...

Where would one get the patch files, and shouldn't they be mentioned on that summary page?

I thought I might look at trying some of the patches to see if they caused the problem, but it's not easy to recompile and reapply and reboot in my setup and I don't have a spare machine to test on at this point that would run the same kernel.

Looking at the summary, I can't see NFS being related, at all, nor the drm radeon nor i915 patches nor ext4 patches (I have NFS in my kernel, but find it unlikely that chanes in the nfs modules would cause this).  
Of course this is against the backdrop of the fact that NONE of the changes look like they should cause symptoms like this...  ;^?

Looking at the trace in comment #5... what's up with frame 184? Wireshark says:

    Bogus IP length (0, less than header length 20)

...I suspect that there's a problem at a lower level than CIFS. Probably something in the networking layer. I'd have a hard look at any networking-related patches that went into 2.6.38.2 and try backing them out one at a time to see if the problem goes away.

Right offhand, maybe commit 3bc0f0aa75 is a candidate to check, but bisecting would probably be the best bet.

I just tried to reproduce this using a fedora 2.6.38.2 kernel:

    2.6.38.2-9.fc15.x86_64

...and wasn't able to do so. It worked fine for me.

Perhaps this is dependent on a particular set of drivers?

Either way, I think we're going to have to depend on Linda to track this down since only she's been able to reproduce it so far (to my knowledge), unless someone here has a good idea of what it might be...

For bisecting:

 git clone git://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-2.6.38.y.git
 cd linux-2.6.38.y 
 git bisect start
 git bisect bad v2.6.38.2
 git bisect good v2.6.38.1 

should get you started...
 

(man git-bisect for more info)

Well, if I can believe the results of this bisect good/bad...
I ended up with:

Ishtar:linux/git/linux-2.6.38.y> git bisect bad
40e499c3a70aeb4d3eb090782d6c899e0fbb3895 is the first bad commit
commit 40e499c3a70aeb4d3eb090782d6c899e0fbb3895
Author: Stefano Stabellini <stefano.stabellini@eu.citrix.com>
Date:   Fri Feb 18 11:32:40 2011 +0000

    xen: set max_pfn_mapped to the last pfn mapped
    
    commit 14988a4d350ce3b41ecad4f63c4f44c56f5ae34d upstream.
    
    Do not set max_pfn_mapped to the end of the initial memory mappings,
    that also contain pages that don't belong in pfn space (like the mfn
    list).
    
    Set max_pfn_mapped to the last real pfn mapped in the initial memory
    mappings that is the pfn backing _end.
    
    Signed-off-by: Stefano Stabellini <stefano.stabellini@eu.citrix.com>
    Acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
    LKML-Reference: <alpine.DEB.2.00.1103171739050.3382@kaball-desktop>
    Signed-off-by: H. Peter Anvin <hpa@zytor.com>
    Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>

:040000 040000 4771d1622b46f3b15e116f6d2b97b4b61acb914f 7dc51f6449c430500f51ed07a1001c505a2a905b M      arch
---

Go figger.

hm.... can you double check by reverting that commit on top of the current stable kernel?

just do: "git revert 40e499c3a70aeb4d3eb090782d6c899e0fbb3895", maybe you need to type git bisect reset, before... maybe saving the git bisect log is a good idea too... , in case you want to double check some good/bad decisions later on) )

So I was supposed to go into my git-bisect tree and do a 'git bisect reset' (giving me what should have been an original copy of 2.6.38.2, yes?).

Then type a 
"git revert 40e499c3a70aeb4d3eb090782d6c899e0fbb389540e499c3a70aeb4d3eb090782d6c899e0fbb3895", which should give me a 2.6.38.2 minus that 1 change (right?).

Build that...and that should have made a working tree (right?).

Well...
    ***something didn't go according to plan***

The resulting tree from above didn't work. :-(.



Starting off on the bisect, I had an error in that I missed a error/warning message that zipped by and I didn't see that my new test kernel hadn't copied/installed, so when I rebooted, I wasn't testing with the right kernel, which resulted in my first git-bisect being done wrong.   Caught it, and went back to beginning w/reset -- and from that point on, double checked results at each phase to ensure I was doing it right.

Still its easily conceivable that something still got messed up along the way given the manual repetitive nature of this process and the long waits between each test cycle (mainly the reboots -- it's a Dell machine and their latest gen machines take the longest of any generation to get through the 'preboot' process before it actually gets to the SW bootloader (both in workstation and server models!).

At each phase, I did:
1) a "cp -al <git-tree> <build-tree>"
2) copy .config from previous build to current build-tree
3) "make oldconfig"
4) "make xconfig", "change suffix", then make ... & call my install script:
   sudo ../doit m"  which copies binaries and modules & runs lilo
5) reboot & test... 


Is there a less error prone way to do this (presuming I messed up somewhere) -- was only about 6-7 steps (from memory), but kept wondering if I was missing something each step of the way...



FWIW, the "git bisect log" looks like:

git bisect start
# bad: [cf6013b4a767169ca105edec2735ef7ff8d9b403] Linux 2.6.38.2
git bisect bad cf6013b4a767169ca105edec2735ef7ff8d9b403
# good: [24d6a9d07f7da6c635530688a43086ea293bf9dc] Linux 2.6.38.1
git bisect good 24d6a9d07f7da6c635530688a43086ea293bf9dc
# bad: [fa70942de94f80025ef55d510192b697798390c6] nfsd4: minor nfs4state.c reshuffling
git bisect bad fa70942de94f80025ef55d510192b697798390c6
# good: [1163d4ca61ff2544f66b2663c6050f5f00c01fc1] oom: prevent unnecessary oom kills or kernel panics
git bisect good 1163d4ca61ff2544f66b2663c6050f5f00c01fc1
# bad: [582d8b9e2879512507b8a9409f85fb1394e1c53e] mm: PageBuddy and mapcount robustness
git bisect bad 582d8b9e2879512507b8a9409f85fb1394e1c53e
# good: [5ea5254aa0ad269cfbd2875c973ef25ab5b5e9db] Input: xen-kbdfront - advertise either absolute or relative coordinates
git bisect good 5ea5254aa0ad269cfbd2875c973ef25ab5b5e9db
# bad: [c93f57068049deb9907ca15ba2501bc5e382e513] Prevent rt_sigqueueinfo and rt_tgsigqueueinfo from spoofing the signal code
git bisect bad c93f57068049deb9907ca15ba2501bc5e382e513
# bad: [40e499c3a70aeb4d3eb090782d6c899e0fbb3895] xen: set max_pfn_mapped to the last pfn mapped
git bisect bad 40e499c3a70aeb4d3eb090782d6c899e0fbb3895

Hm.. I think you botched some good/bad decisions.. You don't have Xen enabled in your .config, so those xen commits shouldn't make a difference. (should as in "if they do what their title suggests)

If you set LOCALVERSION_AUTO = y, you don't have to manually name your kernels. They will automatically be called smth like vmlinuz-2.6.38-rc7-00163-gfb62c00 (or the like).. and the standard 'make install' set's up symlinks to vmlinuz and cp's a backup of the old vmlinuz-symlink to vmlinuz.old... so, if you have grub/lilo set up to use those two symlinks then doing 

make -j4 && su -c 'make install && make modules_install && lilo'

should be sufficient to replace steps 1) - 4) ...

and once you rebooted, you can type uname -r to verify you are on the correct kernel...

You should probably recheck if the nfs4 commit really is bad and -if that is correct- if the oom one is really good...

I simplified my bisection routine and redid it.  

The git-revert on the suspect patch yielded a working kernel, so it seems like the bad patch is:

c93f57068049deb9907ca15ba2501bc5e382e513 is the first bad commit
commit c93f57068049deb9907ca15ba2501bc5e382e513
Author: Julien Tinnes <jln@google.com>
Date:   Fri Mar 18 15:05:21 2011 -0700

    Prevent rt_sigqueueinfo and rt_tgsigqueueinfo from spoofing the signal code
    
    commit da48524eb20662618854bb3df2db01fc65f3070c upstream.
    
    Userland should be able to trust the pid and uid of the sender of a
    signal if the si_code is SI_TKILL.
    
    Unfortunately, the kernel has historically allowed sigqueueinfo() to
    send any si_code at all (as long as it was negative - to distinguish it
    from kernel-generated signals like SIGILL etc), so it could spoof a
    SI_TKILL with incorrect siginfo values.
    
    Happily, it looks like glibc has always set si_code to the appropriate
    SI_QUEUE, so there are probably no actual user code that ever uses
    anything but the appropriate SI_QUEUE flag.
    
    So just tighten the check for si_code (we used to allow any negative
    value), and add a (one-time) warning in case there are binaries out
    there that might depend on using other si_code values.
    
    Signed-off-by: Julien Tinnes <jln@google.com>
    Acked-by: Oleg Nesterov <oleg@redhat.com>
    Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>
    Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>

:040000 040000 ab8f7cd63a1cecee2c9148dcc19722b23edde788 359f36458ebad8dc94c31a6f76d38a176994578b M      kernel

--------------
This corresponds to the following diff between the two source trees:

/home/linux/git/linux-2.6.38.y> diff -rU5 . ../../linux-2.6.38.2/.  
Only in .: .git
diff -rU5 ./kernel/signal.c ../../linux-2.6.38.2/./kernel/signal.c
--- ./kernel/signal.c   2011-04-19 21:13:18.879396295 -0700
+++ ../../linux-2.6.38.2/./kernel/signal.c      2011-03-27 11:37:20.000000000 -0700
@@ -2419,13 +2419,17 @@
 
        if (copy_from_user(&info, uinfo, sizeof(siginfo_t)))
                return -EFAULT;
 
        /* Not even root can pretend to send signals from the kernel.
-          Nor can they impersonate a kill(), which adds source info.  */
-       if (info.si_code >= 0)
+        * Nor can they impersonate a kill()/tgkill(), which adds source info.
+        */
+       if (info.si_code != SI_QUEUE) {
+               /* We used to allow any < 0 si_code */
+               WARN_ON_ONCE(info.si_code < 0);
                return -EPERM;
+       }
        info.si_signo = sig;
 
        /* POSIX.1b doesn't mention process groups.  */
        return kill_proc_info(sig, &info, pid);
 }
@@ -2435,13 +2439,17 @@
        /* This is only valid for single tasks */
        if (pid <= 0 || tgid <= 0)
                return -EINVAL;
 
        /* Not even root can pretend to send signals from the kernel.
-          Nor can they impersonate a kill(), which adds source info.  */
-       if (info->si_code >= 0)
+        * Nor can they impersonate a kill()/tgkill(), which adds source info.
+        */
+       if (info->si_code != SI_QUEUE) {
+               /* We used to allow any < 0 si_code */
+               WARN_ON_ONCE(info->si_code < 0);
                return -EPERM;
+       }
        info->si_signo = sig;
 
        return do_send_specific(tgid, pid, sig, info);
 }
 
---
and the commit:


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


The only relationship I could think of is if the CIFS networking code uses threads and this change somehow changes the behavior for how the first 2-3 RT-signals are used by glibc in its thread management.   

Barring that, it could an unlikely case of this routine pushing memory around causing the bug to trigger, or less likely, a compiler bug.


FWIW, my system's compiler is:

   gcc (SUSE Linux) 4.4.1 [gcc-4_4-branch revision 150839]

First-Bad-Commit: c93f57068049deb9907ca15ba2501bc5e382e513

There is a fix for that commit in 2.6.38.3:

commit 76e61a187353bb6798284196b874938a8fbe3db9
Author: Roland Dreier <roland@purestorage.com>
Date:   Mon Mar 28 14:13:35 2011 -0700

    Relax si_code check in rt_sigqueueinfo and rt_tgsigqueueinfo
    
    commit 243b422af9ea9af4ead07a8ad54c90d4f9b6081a upstream.

Can you test if that also fixes your bug?




On Wed, 20 Apr 2011 00:42:03 -0700
Julien Tinnes <jln@google.com> wrote:

> Hi!
> 
> Thanks for the info, I'll take a look.
> 
> But did you also apply
>
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=243b422af9ea9af4ead07a8ad54c90d4f9b6081a
> ?
> 
> Which should also be somewhere in 2.6.38.
> 
> Julien
> 
> On Tue, Apr 19, 2011 at 10:55 PM, Florian Mickler <florian@mickler.org>
> wrote:
> > Hey Julien,
> >
> > just a note that there was a regression bisected between 2.6.38.1 and
> > 2.6.38.2 as being caused by
> >
> > c93f57068049deb9907ca15ba2501bc5e382e513 is the first bad commit
> > commit c93f57068049deb9907ca15ba2501bc5e382e513
> > Author: Julien Tinnes <jln@google.com>
> > Date:   Fri Mar 18 15:05:21 2011 -0700
> >
> >    Prevent rt_sigqueueinfo and rt_tgsigqueueinfo from spoofing the signal
> code
> >
> >
> > Sadly, the bugzilla only allows to cc bugzilla-account-owners, not
> > arbitrary people, hence this mail.
> >
> >
> > It is tracked in:  https://bugzilla.kernel.org/show_bug.cgi?id=33102
> >
> > Regards,
> > Flo
> >

This bug is not reproducible in 2.6.38.3

This bug was reproducible in 2.6.38.2 and was fixed in 2.6.38.3.

So why the improper change to 'closed unreproducible'?

If you revert the code-fix that fixed the bug it would be reproducible -- wouldn't that be the definition of a code fix?

Indeed.