Re: [REGRESSION] Warning in tcp_fastretrans_alert() of net/ipv4/tcp_input.c

On Wed, Sep 20, 2017 at 6:46 PM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

Hello.

Since, IIRC, v4.11, there is some regression in TCP stack resulting in the
warning shown below. Most of the time it is harmless, but rarely it just
causes either freeze or (I believe, this is related too) panic in
tcp_sacktag_walk() (because sk_buff passed to this function is NULL).
Unfortunately, I still do not have proper stacktrace from panic, but will try
to capture it if possible.

Also, I have custom settings regarding TCP stack, shown below as well. ifb is
used to shape traffic with tc.

Please note this regression was already reported as BZ [1] and as a letter to
ML [2], but got neither attention nor resolution. It is reproducible for (not
only) me on my home router since v4.11 till v4.13.1 incl.

Please advise on how to deal with it. I'll provide any additional info if
necessary, also ready to test patches if any.

Thanks.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=195835
[2] https://urldefense.proofpoint.com/v2/url?u=https-3A__www.spinics.net_lists_netdev_msg436158.html&d=DwIBaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=jJYgtDM7QT-W-Fz_d29HYQ&m=MDDRfLG5DvdOeniMpaZDJI8ulKQ6PQ6OX_1YtRsiTMA&s=-n3dGZw-pQ95kMBUfq5G9nYZFcuWtbTDlYFkcvQPoKc&e= 

We're experiencing the same problems on some machines in our fleet.
Exactly the same symptoms: tcp_fastretrans_alert() warnings and
sometimes panics in tcp_sacktag_walk().

Here is an example of a backtrace with the panic log:

Hi Yuchung!

do you still see the panics if you disable RACK?
sysctl net.ipv4.tcp_recovery=0?

No, we haven't seen any crash since that.

also have you experience any sack reneg? could you post the output of
' nstat |grep -i TCP' thanks

hostname	TcpActiveOpens                  2289680            0.0
hostname	TcpPassiveOpens                 3592758            0.0
hostname	TcpAttemptFails                 746910             0.0
hostname	TcpEstabResets                  154988             0.0
hostname	TcpInSegs                       16258678255        0.0
hostname	TcpOutSegs                      46967011611        0.0
hostname	TcpRetransSegs                  13724310           0.0
hostname	TcpInErrs                       2                  0.0
hostname	TcpOutRsts                      9418798            0.0
hostname	TcpExtEmbryonicRsts             2303               0.0
hostname	TcpExtPruneCalled               90192              0.0
hostname	TcpExtOfoPruned                 57274              0.0
hostname	TcpExtOutOfWindowIcmps          3                  0.0
hostname	TcpExtTW                        1164705            0.0
hostname	TcpExtTWRecycled                2                  0.0
hostname	TcpExtPAWSEstab                 159                0.0
hostname	TcpExtDelayedACKs               209207209          0.0
hostname	TcpExtDelayedACKLocked          508571             0.0
hostname	TcpExtDelayedACKLost            1713248            0.0
hostname	TcpExtListenOverflows           625                0.0
hostname	TcpExtListenDrops               625                0.0
hostname	TcpExtTCPHPHits                 9341188489         0.0
hostname	TcpExtTCPPureAcks               1434646465         0.0
hostname	TcpExtTCPHPAcks                 5733614672         0.0
hostname	TcpExtTCPSackRecovery           3261698            0.0
hostname	TcpExtTCPSACKReneging           12203              0.0
hostname	TcpExtTCPSACKReorder            433189             0.0
hostname	TcpExtTCPTSReorder              22694              0.0
hostname	TcpExtTCPFullUndo               45092              0.0
hostname	TcpExtTCPPartialUndo            22016              0.0
hostname	TcpExtTCPLossUndo               2150040            0.0
hostname	TcpExtTCPLostRetransmit         60119              0.0
hostname	TcpExtTCPSackFailures           2626782            0.0
hostname	TcpExtTCPLossFailures           182999             0.0
hostname	TcpExtTCPFastRetrans            4334275            0.0
hostname	TcpExtTCPSlowStartRetrans       3453348            0.0
hostname	TcpExtTCPTimeouts               1070997            0.0
hostname	TcpExtTCPLossProbes             2633545            0.0
hostname	TcpExtTCPLossProbeRecovery      941647             0.0
hostname	TcpExtTCPSackRecoveryFail       336302             0.0
hostname	TcpExtTCPRcvCollapsed           461354             0.0
hostname	TcpExtTCPAbortOnData            349196             0.0
hostname	TcpExtTCPAbortOnClose           3395               0.0
hostname	TcpExtTCPAbortOnTimeout         51201              0.0
hostname	TcpExtTCPMemoryPressures        2                  0.0
hostname	TcpExtTCPSpuriousRTOs           2120503            0.0
hostname	TcpExtTCPSackShifted            2613736            0.0
hostname	TcpExtTCPSackMerged             21358743           0.0
hostname	TcpExtTCPSackShiftFallback      8769387            0.0
hostname	TcpExtTCPBacklogDrop            5                  0.0
hostname	TcpExtTCPRetransFail            843                0.0
hostname	TcpExtTCPRcvCoalesce            949068035          0.0
hostname	TcpExtTCPOFOQueue               470118             0.0
hostname	TcpExtTCPOFODrop                9915               0.0
hostname	TcpExtTCPOFOMerge               9                  0.0
hostname	TcpExtTCPChallengeACK           90                 0.0
hostname	TcpExtTCPSYNChallenge           3                  0.0
hostname	TcpExtTCPFastOpenActive         2089               0.0
hostname	TcpExtTCPSpuriousRtxHostQueues  896596             0.0
hostname	TcpExtTCPAutoCorking            547386735          0.0
hostname	TcpExtTCPFromZeroWindowAdv      28757              0.0
hostname	TcpExtTCPToZeroWindowAdv        28761              0.0
hostname	TcpExtTCPWantZeroWindowAdv      322431             0.0
hostname	TcpExtTCPSynRetrans             3026               0.0
hostname	TcpExtTCPOrigDataSent           40976870977        0.0
hostname	TcpExtTCPHystartTrainDetect     453920             0.0
hostname	TcpExtTCPHystartTrainCwnd       11586273           0.0
hostname	TcpExtTCPHystartDelayDetect     10943              0.0
hostname	TcpExtTCPHystartDelayCwnd       763554             0.0
hostname	TcpExtTCPACKSkippedPAWS         30                 0.0
hostname	TcpExtTCPACKSkippedSeq          218                0.0
hostname	TcpExtTCPWinProbe               2408               0.0
hostname	TcpExtTCPKeepAlive              213768             0.0
hostname	TcpExtTCPMTUPFail               69                 0.0
hostname	TcpExtTCPMTUPSuccess            8811               0.0

Thanks!

On Tue, Sep 26, 2017 at 6:10 AM, Roman Gushchin [off-list ref] wrote:

quoted

On Wed, Sep 20, 2017 at 6:46 PM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

Hello.

Since, IIRC, v4.11, there is some regression in TCP stack resulting in the
warning shown below. Most of the time it is harmless, but rarely it just
causes either freeze or (I believe, this is related too) panic in
tcp_sacktag_walk() (because sk_buff passed to this function is NULL).
Unfortunately, I still do not have proper stacktrace from panic, but will try
to capture it if possible.

Also, I have custom settings regarding TCP stack, shown below as well. ifb is
used to shape traffic with tc.

Please note this regression was already reported as BZ [1] and as a letter to
ML [2], but got neither attention nor resolution. It is reproducible for (not
only) me on my home router since v4.11 till v4.13.1 incl.

Please advise on how to deal with it. I'll provide any additional info if
necessary, also ready to test patches if any.

Thanks.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=195835
[2] https://urldefense.proofpoint.com/v2/url?u=https-3A__www.spinics.net_lists_netdev_msg436158.html&d=DwIBaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=jJYgtDM7QT-W-Fz_d29HYQ&m=MDDRfLG5DvdOeniMpaZDJI8ulKQ6PQ6OX_1YtRsiTMA&s=-n3dGZw-pQ95kMBUfq5G9nYZFcuWtbTDlYFkcvQPoKc&e=

We're experiencing the same problems on some machines in our fleet.
Exactly the same symptoms: tcp_fastretrans_alert() warnings and
sometimes panics in tcp_sacktag_walk().

Here is an example of a backtrace with the panic log:

Hi Yuchung!

quoted

do you still see the panics if you disable RACK?
sysctl net.ipv4.tcp_recovery=0?

No, we haven't seen any crash since that.

I am out of ideas how RACK can potentially cause tcp_sacktag_walk to
take an empty skb :-( Do you have stack trace or any hint on which call
to tcp-sacktag_walk triggered the panic? internally at Google we never
see that.

quoted

also have you experience any sack reneg? could you post the output of
' nstat |grep -i TCP' thanks

hostname        TcpActiveOpens                  2289680            0.0
hostname        TcpPassiveOpens                 3592758            0.0
hostname        TcpAttemptFails                 746910             0.0
hostname        TcpEstabResets                  154988             0.0
hostname        TcpInSegs                       16258678255        0.0
hostname        TcpOutSegs                      46967011611        0.0
hostname        TcpRetransSegs                  13724310           0.0
hostname        TcpInErrs                       2                  0.0
hostname        TcpOutRsts                      9418798            0.0
hostname        TcpExtEmbryonicRsts             2303               0.0
hostname        TcpExtPruneCalled               90192              0.0
hostname        TcpExtOfoPruned                 57274              0.0
hostname        TcpExtOutOfWindowIcmps          3                  0.0
hostname        TcpExtTW                        1164705            0.0
hostname        TcpExtTWRecycled                2                  0.0
hostname        TcpExtPAWSEstab                 159                0.0
hostname        TcpExtDelayedACKs               209207209          0.0
hostname        TcpExtDelayedACKLocked          508571             0.0
hostname        TcpExtDelayedACKLost            1713248            0.0
hostname        TcpExtListenOverflows           625                0.0
hostname        TcpExtListenDrops               625                0.0
hostname        TcpExtTCPHPHits                 9341188489         0.0
hostname        TcpExtTCPPureAcks               1434646465         0.0
hostname        TcpExtTCPHPAcks                 5733614672         0.0
hostname        TcpExtTCPSackRecovery           3261698            0.0
hostname        TcpExtTCPSACKReneging           12203              0.0
hostname        TcpExtTCPSACKReorder            433189             0.0
hostname        TcpExtTCPTSReorder              22694              0.0
hostname        TcpExtTCPFullUndo               45092              0.0
hostname        TcpExtTCPPartialUndo            22016              0.0
hostname        TcpExtTCPLossUndo               2150040            0.0
hostname        TcpExtTCPLostRetransmit         60119              0.0
hostname        TcpExtTCPSackFailures           2626782            0.0
hostname        TcpExtTCPLossFailures           182999             0.0
hostname        TcpExtTCPFastRetrans            4334275            0.0
hostname        TcpExtTCPSlowStartRetrans       3453348            0.0
hostname        TcpExtTCPTimeouts               1070997            0.0
hostname        TcpExtTCPLossProbes             2633545            0.0
hostname        TcpExtTCPLossProbeRecovery      941647             0.0
hostname        TcpExtTCPSackRecoveryFail       336302             0.0
hostname        TcpExtTCPRcvCollapsed           461354             0.0
hostname        TcpExtTCPAbortOnData            349196             0.0
hostname        TcpExtTCPAbortOnClose           3395               0.0
hostname        TcpExtTCPAbortOnTimeout         51201              0.0
hostname        TcpExtTCPMemoryPressures        2                  0.0
hostname        TcpExtTCPSpuriousRTOs           2120503            0.0
hostname        TcpExtTCPSackShifted            2613736            0.0
hostname        TcpExtTCPSackMerged             21358743           0.0
hostname        TcpExtTCPSackShiftFallback      8769387            0.0
hostname        TcpExtTCPBacklogDrop            5                  0.0
hostname        TcpExtTCPRetransFail            843                0.0
hostname        TcpExtTCPRcvCoalesce            949068035          0.0
hostname        TcpExtTCPOFOQueue               470118             0.0
hostname        TcpExtTCPOFODrop                9915               0.0
hostname        TcpExtTCPOFOMerge               9                  0.0
hostname        TcpExtTCPChallengeACK           90                 0.0
hostname        TcpExtTCPSYNChallenge           3                  0.0
hostname        TcpExtTCPFastOpenActive         2089               0.0
hostname        TcpExtTCPSpuriousRtxHostQueues  896596             0.0
hostname        TcpExtTCPAutoCorking            547386735          0.0
hostname        TcpExtTCPFromZeroWindowAdv      28757              0.0
hostname        TcpExtTCPToZeroWindowAdv        28761              0.0
hostname        TcpExtTCPWantZeroWindowAdv      322431             0.0
hostname        TcpExtTCPSynRetrans             3026               0.0
hostname        TcpExtTCPOrigDataSent           40976870977        0.0
hostname        TcpExtTCPHystartTrainDetect     453920             0.0
hostname        TcpExtTCPHystartTrainCwnd       11586273           0.0
hostname        TcpExtTCPHystartDelayDetect     10943              0.0
hostname        TcpExtTCPHystartDelayCwnd       763554             0.0
hostname        TcpExtTCPACKSkippedPAWS         30                 0.0
hostname        TcpExtTCPACKSkippedSeq          218                0.0
hostname        TcpExtTCPWinProbe               2408               0.0
hostname        TcpExtTCPKeepAlive              213768             0.0
hostname        TcpExtTCPMTUPFail               69                 0.0
hostname        TcpExtTCPMTUPSuccess            8811               0.0

Thanks!

On Tue, Sep 26, 2017 at 5:12 PM, Yuchung Cheng [off-list ref] wrote:

On Tue, Sep 26, 2017 at 6:10 AM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

On Wed, Sep 20, 2017 at 6:46 PM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

Hello.

Since, IIRC, v4.11, there is some regression in TCP stack resulting in the
warning shown below. Most of the time it is harmless, but rarely it just
causes either freeze or (I believe, this is related too) panic in
tcp_sacktag_walk() (because sk_buff passed to this function is NULL).
Unfortunately, I still do not have proper stacktrace from panic, but will try
to capture it if possible.

Also, I have custom settings regarding TCP stack, shown below as well. ifb is
used to shape traffic with tc.

Please note this regression was already reported as BZ [1] and as a letter to
ML [2], but got neither attention nor resolution. It is reproducible for (not
only) me on my home router since v4.11 till v4.13.1 incl.

Please advise on how to deal with it. I'll provide any additional info if
necessary, also ready to test patches if any.

Thanks.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=195835
[2] https://urldefense.proofpoint.com/v2/url?u=https-3A__www.spinics.net_lists_netdev_msg436158.html&d=DwIBaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=jJYgtDM7QT-W-Fz_d29HYQ&m=MDDRfLG5DvdOeniMpaZDJI8ulKQ6PQ6OX_1YtRsiTMA&s=-n3dGZw-pQ95kMBUfq5G9nYZFcuWtbTDlYFkcvQPoKc&e=

We're experiencing the same problems on some machines in our fleet.
Exactly the same symptoms: tcp_fastretrans_alert() warnings and
sometimes panics in tcp_sacktag_walk().

Here is an example of a backtrace with the panic log:

Hi Yuchung!

quoted

do you still see the panics if you disable RACK?
sysctl net.ipv4.tcp_recovery=0?

No, we haven't seen any crash since that.

I am out of ideas how RACK can potentially cause tcp_sacktag_walk to
take an empty skb :-( Do you have stack trace or any hint on which call
to tcp-sacktag_walk triggered the panic? internally at Google we never
see that.

hmm something just struck me: could you try
sysctl net.ipv4.tcp_recovery=1 net.ipv4.tcp_retrans_collapse=0
and see if kernel still panics on sack processing?

quoted

quoted

also have you experience any sack reneg? could you post the output of
' nstat |grep -i TCP' thanks

hostname        TcpActiveOpens                  2289680            0.0
hostname        TcpPassiveOpens                 3592758            0.0
hostname        TcpAttemptFails                 746910             0.0
hostname        TcpEstabResets                  154988             0.0
hostname        TcpInSegs                       16258678255        0.0
hostname        TcpOutSegs                      46967011611        0.0
hostname        TcpRetransSegs                  13724310           0.0
hostname        TcpInErrs                       2                  0.0
hostname        TcpOutRsts                      9418798            0.0
hostname        TcpExtEmbryonicRsts             2303               0.0
hostname        TcpExtPruneCalled               90192              0.0
hostname        TcpExtOfoPruned                 57274              0.0
hostname        TcpExtOutOfWindowIcmps          3                  0.0
hostname        TcpExtTW                        1164705            0.0
hostname        TcpExtTWRecycled                2                  0.0
hostname        TcpExtPAWSEstab                 159                0.0
hostname        TcpExtDelayedACKs               209207209          0.0
hostname        TcpExtDelayedACKLocked          508571             0.0
hostname        TcpExtDelayedACKLost            1713248            0.0
hostname        TcpExtListenOverflows           625                0.0
hostname        TcpExtListenDrops               625                0.0
hostname        TcpExtTCPHPHits                 9341188489         0.0
hostname        TcpExtTCPPureAcks               1434646465         0.0
hostname        TcpExtTCPHPAcks                 5733614672         0.0
hostname        TcpExtTCPSackRecovery           3261698            0.0
hostname        TcpExtTCPSACKReneging           12203              0.0
hostname        TcpExtTCPSACKReorder            433189             0.0
hostname        TcpExtTCPTSReorder              22694              0.0
hostname        TcpExtTCPFullUndo               45092              0.0
hostname        TcpExtTCPPartialUndo            22016              0.0
hostname        TcpExtTCPLossUndo               2150040            0.0
hostname        TcpExtTCPLostRetransmit         60119              0.0
hostname        TcpExtTCPSackFailures           2626782            0.0
hostname        TcpExtTCPLossFailures           182999             0.0
hostname        TcpExtTCPFastRetrans            4334275            0.0
hostname        TcpExtTCPSlowStartRetrans       3453348            0.0
hostname        TcpExtTCPTimeouts               1070997            0.0
hostname        TcpExtTCPLossProbes             2633545            0.0
hostname        TcpExtTCPLossProbeRecovery      941647             0.0
hostname        TcpExtTCPSackRecoveryFail       336302             0.0
hostname        TcpExtTCPRcvCollapsed           461354             0.0
hostname        TcpExtTCPAbortOnData            349196             0.0
hostname        TcpExtTCPAbortOnClose           3395               0.0
hostname        TcpExtTCPAbortOnTimeout         51201              0.0
hostname        TcpExtTCPMemoryPressures        2                  0.0
hostname        TcpExtTCPSpuriousRTOs           2120503            0.0
hostname        TcpExtTCPSackShifted            2613736            0.0
hostname        TcpExtTCPSackMerged             21358743           0.0
hostname        TcpExtTCPSackShiftFallback      8769387            0.0
hostname        TcpExtTCPBacklogDrop            5                  0.0
hostname        TcpExtTCPRetransFail            843                0.0
hostname        TcpExtTCPRcvCoalesce            949068035          0.0
hostname        TcpExtTCPOFOQueue               470118             0.0
hostname        TcpExtTCPOFODrop                9915               0.0
hostname        TcpExtTCPOFOMerge               9                  0.0
hostname        TcpExtTCPChallengeACK           90                 0.0
hostname        TcpExtTCPSYNChallenge           3                  0.0
hostname        TcpExtTCPFastOpenActive         2089               0.0
hostname        TcpExtTCPSpuriousRtxHostQueues  896596             0.0
hostname        TcpExtTCPAutoCorking            547386735          0.0
hostname        TcpExtTCPFromZeroWindowAdv      28757              0.0
hostname        TcpExtTCPToZeroWindowAdv        28761              0.0
hostname        TcpExtTCPWantZeroWindowAdv      322431             0.0
hostname        TcpExtTCPSynRetrans             3026               0.0
hostname        TcpExtTCPOrigDataSent           40976870977        0.0
hostname        TcpExtTCPHystartTrainDetect     453920             0.0
hostname        TcpExtTCPHystartTrainCwnd       11586273           0.0
hostname        TcpExtTCPHystartDelayDetect     10943              0.0
hostname        TcpExtTCPHystartDelayCwnd       763554             0.0
hostname        TcpExtTCPACKSkippedPAWS         30                 0.0
hostname        TcpExtTCPACKSkippedSeq          218                0.0
hostname        TcpExtTCPWinProbe               2408               0.0
hostname        TcpExtTCPKeepAlive              213768             0.0
hostname        TcpExtTCPMTUPFail               69                 0.0
hostname        TcpExtTCPMTUPSuccess            8811               0.0

Thanks!

Hi.

Won't tell about panic in tcp_sacktag_walk() since I cannot trigger it 
intentionally, but setting net.ipv4.tcp_retrans_collapse to 0 *does not* fix 
warning in tcp_fastretrans_alert() for me.

On středa 27. září 2017 2:18:32 CEST Yuchung Cheng wrote:

On Tue, Sep 26, 2017 at 5:12 PM, Yuchung Cheng [off-list ref] wrote:

quoted

On Tue, Sep 26, 2017 at 6:10 AM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

On Wed, Sep 20, 2017 at 6:46 PM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

Hello.

Since, IIRC, v4.11, there is some regression in TCP stack resulting
in the
warning shown below. Most of the time it is harmless, but rarely it
just
causes either freeze or (I believe, this is related too) panic in
tcp_sacktag_walk() (because sk_buff passed to this function is
NULL).
Unfortunately, I still do not have proper stacktrace from panic, but
will try to capture it if possible.

Also, I have custom settings regarding TCP stack, shown below as
well. ifb is used to shape traffic with tc.

Please note this regression was already reported as BZ [1] and as a
letter to ML [2], but got neither attention nor resolution. It is
reproducible for (not only) me on my home router since v4.11 till
v4.13.1 incl.

Please advise on how to deal with it. I'll provide any additional
info if
necessary, also ready to test patches if any.

Thanks.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=195835
[2]
https://urldefense.proofpoint.com/v2/url?u=https-3A__www.spinics.ne
t_lists_netdev_msg436158.html&d=DwIBaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=jJ
YgtDM7QT-W-Fz_d29HYQ&m=MDDRfLG5DvdOeniMpaZDJI8ulKQ6PQ6OX_1YtRsiTMA&s
=-n3dGZw-pQ95kMBUfq5G9nYZFcuWtbTDlYFkcvQPoKc&e=>>> > 

We're experiencing the same problems on some machines in our fleet.
Exactly the same symptoms: tcp_fastretrans_alert() warnings and
sometimes panics in tcp_sacktag_walk().

quoted

quoted

Here is an example of a backtrace with the panic log:

Hi Yuchung!

quoted

do you still see the panics if you disable RACK?
sysctl net.ipv4.tcp_recovery=0?

No, we haven't seen any crash since that.

I am out of ideas how RACK can potentially cause tcp_sacktag_walk to
take an empty skb :-( Do you have stack trace or any hint on which call
to tcp-sacktag_walk triggered the panic? internally at Google we never
see that.

hmm something just struck me: could you try
sysctl net.ipv4.tcp_recovery=1 net.ipv4.tcp_retrans_collapse=0
and see if kernel still panics on sack processing?

quoted

quoted

quoted

also have you experience any sack reneg? could you post the output of
' nstat |grep -i TCP' thanks

hostname        TcpActiveOpens                  2289680            0.0
hostname        TcpPassiveOpens                 3592758            0.0
hostname        TcpAttemptFails                 746910             0.0
hostname        TcpEstabResets                  154988             0.0
hostname        TcpInSegs                       16258678255        0.0
hostname        TcpOutSegs                      46967011611        0.0
hostname        TcpRetransSegs                  13724310           0.0
hostname        TcpInErrs                       2                  0.0
hostname        TcpOutRsts                      9418798            0.0
hostname        TcpExtEmbryonicRsts             2303               0.0
hostname        TcpExtPruneCalled               90192              0.0
hostname        TcpExtOfoPruned                 57274              0.0
hostname        TcpExtOutOfWindowIcmps          3                  0.0
hostname        TcpExtTW                        1164705            0.0
hostname        TcpExtTWRecycled                2                  0.0
hostname        TcpExtPAWSEstab                 159                0.0
hostname        TcpExtDelayedACKs               209207209          0.0
hostname        TcpExtDelayedACKLocked          508571             0.0
hostname        TcpExtDelayedACKLost            1713248            0.0
hostname        TcpExtListenOverflows           625                0.0
hostname        TcpExtListenDrops               625                0.0
hostname        TcpExtTCPHPHits                 9341188489         0.0
hostname        TcpExtTCPPureAcks               1434646465         0.0
hostname        TcpExtTCPHPAcks                 5733614672         0.0
hostname        TcpExtTCPSackRecovery           3261698            0.0
hostname        TcpExtTCPSACKReneging           12203              0.0
hostname        TcpExtTCPSACKReorder            433189             0.0
hostname        TcpExtTCPTSReorder              22694              0.0
hostname        TcpExtTCPFullUndo               45092              0.0
hostname        TcpExtTCPPartialUndo            22016              0.0
hostname        TcpExtTCPLossUndo               2150040            0.0
hostname        TcpExtTCPLostRetransmit         60119              0.0
hostname        TcpExtTCPSackFailures           2626782            0.0
hostname        TcpExtTCPLossFailures           182999             0.0
hostname        TcpExtTCPFastRetrans            4334275            0.0
hostname        TcpExtTCPSlowStartRetrans       3453348            0.0
hostname        TcpExtTCPTimeouts               1070997            0.0
hostname        TcpExtTCPLossProbes             2633545            0.0
hostname        TcpExtTCPLossProbeRecovery      941647             0.0
hostname        TcpExtTCPSackRecoveryFail       336302             0.0
hostname        TcpExtTCPRcvCollapsed           461354             0.0
hostname        TcpExtTCPAbortOnData            349196             0.0
hostname        TcpExtTCPAbortOnClose           3395               0.0
hostname        TcpExtTCPAbortOnTimeout         51201              0.0
hostname        TcpExtTCPMemoryPressures        2                  0.0
hostname        TcpExtTCPSpuriousRTOs           2120503            0.0
hostname        TcpExtTCPSackShifted            2613736            0.0
hostname        TcpExtTCPSackMerged             21358743           0.0
hostname        TcpExtTCPSackShiftFallback      8769387            0.0
hostname        TcpExtTCPBacklogDrop            5                  0.0
hostname        TcpExtTCPRetransFail            843                0.0
hostname        TcpExtTCPRcvCoalesce            949068035          0.0
hostname        TcpExtTCPOFOQueue               470118             0.0
hostname        TcpExtTCPOFODrop                9915               0.0
hostname        TcpExtTCPOFOMerge               9                  0.0
hostname        TcpExtTCPChallengeACK           90                 0.0
hostname        TcpExtTCPSYNChallenge           3                  0.0
hostname        TcpExtTCPFastOpenActive         2089               0.0
hostname        TcpExtTCPSpuriousRtxHostQueues  896596             0.0
hostname        TcpExtTCPAutoCorking            547386735          0.0
hostname        TcpExtTCPFromZeroWindowAdv      28757              0.0
hostname        TcpExtTCPToZeroWindowAdv        28761              0.0
hostname        TcpExtTCPWantZeroWindowAdv      322431             0.0
hostname        TcpExtTCPSynRetrans             3026               0.0
hostname        TcpExtTCPOrigDataSent           40976870977        0.0
hostname        TcpExtTCPHystartTrainDetect     453920             0.0
hostname        TcpExtTCPHystartTrainCwnd       11586273           0.0
hostname        TcpExtTCPHystartDelayDetect     10943              0.0
hostname        TcpExtTCPHystartDelayCwnd       763554             0.0
hostname        TcpExtTCPACKSkippedPAWS         30                 0.0
hostname        TcpExtTCPACKSkippedSeq          218                0.0
hostname        TcpExtTCPWinProbe               2408               0.0
hostname        TcpExtTCPKeepAlive              213768             0.0
hostname        TcpExtTCPMTUPFail               69                 0.0
hostname        TcpExtTCPMTUPSuccess            8811               0.0

Thanks!

On Thu, Sep 28, 2017 at 1:14 AM, Oleksandr Natalenko
[off-list ref] wrote:

Hi.

Won't tell about panic in tcp_sacktag_walk() since I cannot trigger it
intentionally, but setting net.ipv4.tcp_retrans_collapse to 0 *does not* fix
warning in tcp_fastretrans_alert() for me.

Hi Oleksandr: no retrans_collapse should not matter for that warning
in tcp_fstretrans_alert(). the warning as I explained earlier is
likely false. Neal and I are more concerned the panic in
tcp_sacktag_walk. This is just a blind shot but thx for retrying.

We can submit a one-liner to remove the fast retrans warning but want
to nail the bigger issue first.

On středa 27. září 2017 2:18:32 CEST Yuchung Cheng wrote:

quoted

On Tue, Sep 26, 2017 at 5:12 PM, Yuchung Cheng [off-list ref] wrote:

quoted

On Tue, Sep 26, 2017 at 6:10 AM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

On Wed, Sep 20, 2017 at 6:46 PM, Roman Gushchin [off-list ref] wrote:

quoted

quoted

Hello.

Since, IIRC, v4.11, there is some regression in TCP stack resulting
in the
warning shown below. Most of the time it is harmless, but rarely it
just
causes either freeze or (I believe, this is related too) panic in
tcp_sacktag_walk() (because sk_buff passed to this function is
NULL).
Unfortunately, I still do not have proper stacktrace from panic, but
will try to capture it if possible.

Also, I have custom settings regarding TCP stack, shown below as
well. ifb is used to shape traffic with tc.

Please note this regression was already reported as BZ [1] and as a
letter to ML [2], but got neither attention nor resolution. It is
reproducible for (not only) me on my home router since v4.11 till
v4.13.1 incl.

Please advise on how to deal with it. I'll provide any additional
info if
necessary, also ready to test patches if any.

Thanks.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=195835
[2]
https://urldefense.proofpoint.com/v2/url?u=https-3A__www.spinics.ne
t_lists_netdev_msg436158.html&d=DwIBaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=jJ
YgtDM7QT-W-Fz_d29HYQ&m=MDDRfLG5DvdOeniMpaZDJI8ulKQ6PQ6OX_1YtRsiTMA&s
=-n3dGZw-pQ95kMBUfq5G9nYZFcuWtbTDlYFkcvQPoKc&e=>>> >

We're experiencing the same problems on some machines in our fleet.
Exactly the same symptoms: tcp_fastretrans_alert() warnings and
sometimes panics in tcp_sacktag_walk().

quoted

quoted

Here is an example of a backtrace with the panic log:

Hi Yuchung!

quoted

do you still see the panics if you disable RACK?
sysctl net.ipv4.tcp_recovery=0?

No, we haven't seen any crash since that.

I am out of ideas how RACK can potentially cause tcp_sacktag_walk to
take an empty skb :-( Do you have stack trace or any hint on which call
to tcp-sacktag_walk triggered the panic? internally at Google we never
see that.

hmm something just struck me: could you try
sysctl net.ipv4.tcp_recovery=1 net.ipv4.tcp_retrans_collapse=0
and see if kernel still panics on sack processing?

quoted

quoted

quoted

also have you experience any sack reneg? could you post the output of
' nstat |grep -i TCP' thanks

hostname        TcpActiveOpens                  2289680            0.0
hostname        TcpPassiveOpens                 3592758            0.0
hostname        TcpAttemptFails                 746910             0.0
hostname        TcpEstabResets                  154988             0.0
hostname        TcpInSegs                       16258678255        0.0
hostname        TcpOutSegs                      46967011611        0.0
hostname        TcpRetransSegs                  13724310           0.0
hostname        TcpInErrs                       2                  0.0
hostname        TcpOutRsts                      9418798            0.0
hostname        TcpExtEmbryonicRsts             2303               0.0
hostname        TcpExtPruneCalled               90192              0.0
hostname        TcpExtOfoPruned                 57274              0.0
hostname        TcpExtOutOfWindowIcmps          3                  0.0
hostname        TcpExtTW                        1164705            0.0
hostname        TcpExtTWRecycled                2                  0.0
hostname        TcpExtPAWSEstab                 159                0.0
hostname        TcpExtDelayedACKs               209207209          0.0
hostname        TcpExtDelayedACKLocked          508571             0.0
hostname        TcpExtDelayedACKLost            1713248            0.0
hostname        TcpExtListenOverflows           625                0.0
hostname        TcpExtListenDrops               625                0.0
hostname        TcpExtTCPHPHits                 9341188489         0.0
hostname        TcpExtTCPPureAcks               1434646465         0.0
hostname        TcpExtTCPHPAcks                 5733614672         0.0
hostname        TcpExtTCPSackRecovery           3261698            0.0
hostname        TcpExtTCPSACKReneging           12203              0.0
hostname        TcpExtTCPSACKReorder            433189             0.0
hostname        TcpExtTCPTSReorder              22694              0.0
hostname        TcpExtTCPFullUndo               45092              0.0
hostname        TcpExtTCPPartialUndo            22016              0.0
hostname        TcpExtTCPLossUndo               2150040            0.0
hostname        TcpExtTCPLostRetransmit         60119              0.0
hostname        TcpExtTCPSackFailures           2626782            0.0
hostname        TcpExtTCPLossFailures           182999             0.0
hostname        TcpExtTCPFastRetrans            4334275            0.0
hostname        TcpExtTCPSlowStartRetrans       3453348            0.0
hostname        TcpExtTCPTimeouts               1070997            0.0
hostname        TcpExtTCPLossProbes             2633545            0.0
hostname        TcpExtTCPLossProbeRecovery      941647             0.0
hostname        TcpExtTCPSackRecoveryFail       336302             0.0
hostname        TcpExtTCPRcvCollapsed           461354             0.0
hostname        TcpExtTCPAbortOnData            349196             0.0
hostname        TcpExtTCPAbortOnClose           3395               0.0
hostname        TcpExtTCPAbortOnTimeout         51201              0.0
hostname        TcpExtTCPMemoryPressures        2                  0.0
hostname        TcpExtTCPSpuriousRTOs           2120503            0.0
hostname        TcpExtTCPSackShifted            2613736            0.0
hostname        TcpExtTCPSackMerged             21358743           0.0
hostname        TcpExtTCPSackShiftFallback      8769387            0.0
hostname        TcpExtTCPBacklogDrop            5                  0.0
hostname        TcpExtTCPRetransFail            843                0.0
hostname        TcpExtTCPRcvCoalesce            949068035          0.0
hostname        TcpExtTCPOFOQueue               470118             0.0
hostname        TcpExtTCPOFODrop                9915               0.0
hostname        TcpExtTCPOFOMerge               9                  0.0
hostname        TcpExtTCPChallengeACK           90                 0.0
hostname        TcpExtTCPSYNChallenge           3                  0.0
hostname        TcpExtTCPFastOpenActive         2089               0.0
hostname        TcpExtTCPSpuriousRtxHostQueues  896596             0.0
hostname        TcpExtTCPAutoCorking            547386735          0.0
hostname        TcpExtTCPFromZeroWindowAdv      28757              0.0
hostname        TcpExtTCPToZeroWindowAdv        28761              0.0
hostname        TcpExtTCPWantZeroWindowAdv      322431             0.0
hostname        TcpExtTCPSynRetrans             3026               0.0
hostname        TcpExtTCPOrigDataSent           40976870977        0.0
hostname        TcpExtTCPHystartTrainDetect     453920             0.0
hostname        TcpExtTCPHystartTrainCwnd       11586273           0.0
hostname        TcpExtTCPHystartDelayDetect     10943              0.0
hostname        TcpExtTCPHystartDelayCwnd       763554             0.0
hostname        TcpExtTCPACKSkippedPAWS         30                 0.0
hostname        TcpExtTCPACKSkippedSeq          218                0.0
hostname        TcpExtTCPWinProbe               2408               0.0
hostname        TcpExtTCPKeepAlive              213768             0.0
hostname        TcpExtTCPMTUPFail               69                 0.0
hostname        TcpExtTCPMTUPSuccess            8811               0.0

Thanks!

On Thu, Sep 28, 2017 at 04:36:58PM -0700, Yuchung Cheng wrote:

On Thu, Sep 28, 2017 at 1:14 AM, Oleksandr Natalenko
[off-list ref] wrote:

quoted

Hi.

Won't tell about panic in tcp_sacktag_walk() since I cannot trigger it
intentionally, but setting net.ipv4.tcp_retrans_collapse to 0 *does not* fix
warning in tcp_fastretrans_alert() for me.

Hi Oleksandr: no retrans_collapse should not matter for that warning
in tcp_fstretrans_alert(). the warning as I explained earlier is
likely false. Neal and I are more concerned the panic in
tcp_sacktag_walk. This is just a blind shot but thx for retrying.

We can submit a one-liner to remove the fast retrans warning but want
to nail the bigger issue first.

we're still seeing the warnings followed by crashes and it's very concerning.
We hoped that most recent Neal's patches from Sep 18 around this area may
magically fix the issue, but no. The panics are still there.
It's confirmed that net.ipv4.tcp_retrans_collapse=0 does not help
whereas net.ipv4.tcp_recovery=0 works, but obviously undesirable.
We're out of ideas on how to debug this.

Warning + panic:
[ 7678.309043] Call Trace:
[ 7678.313925]  <IRQ>
[ 7678.317955]  dump_stack+0x4d/0x70
[ 7678.324573]  __warn+0xd3/0xf0
[ 7678.330497]  warn_slowpath_null+0x1e/0x20
[ 7678.338510]  tcp_fastretrans_alert+0xacf/0xbd0
[ 7678.347380]  tcp_ack+0xbce/0x1390
[ 7678.354006]  tcp_rcv_established+0x1ce/0x740
[ 7678.362536]  tcp_v6_do_rcv+0x15b/0x400
[ 7678.370025]  tcp_v6_rcv+0x94c/0x9f0
[ 7678.376989]  ? tcp_rcv_established+0x42b/0x740
[ 7678.385866]  ip6_input_finish+0xea/0x430
[ 7678.393702]  ip6_input+0x32/0xa0
[ 7678.400155]  ? ip6_rcv_finish+0xa0/0xa0
[ 7678.407834]  ip6_rcv_finish+0x4b/0xa0
[ 7678.415164]  ipv6_rcv+0x2ec/0x4f0
[ 7678.421778]  ? ip6_make_skb+0x1c0/0x1c0
[ 7678.429447]  __netif_receive_skb_core+0x2d5/0x9a0
[ 7678.438845]  ? tcp6_gro_receive+0x11d/0x1c0
[ 7678.447211]  ? ipv6_gro_receive+0x1d0/0x380
[ 7678.455566]  __netif_receive_skb+0x16/0x70
[ 7678.463748]  netif_receive_skb_internal+0x32/0x3b0
[ 7678.473318]  ? dev_gro_receive+0x27c/0x470
[ 7678.481502]  napi_gro_receive+0x113/0x1d0
[ 7678.489510]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[ 7678.499077]  mlx5e_poll_rx_cq+0x79/0x830
[ 7678.506911]  mlx5e_napi_poll+0x8c/0x3d0
[ 7678.514579]  ? mlx5_cq_completion+0x54/0xb0
[ 7678.522950]  net_rx_action+0x22e/0x380
[ 7678.530450]  __do_softirq+0x106/0x2e8
[ 7678.537768]  irq_exit+0xb0/0xc0
[ 7678.544042]  do_IRQ+0x4f/0xd0
[ 7678.549970]  common_interrupt+0x86/0x86
...
[ 7685.690697] BUG: unable to handle kernel 
[ 7685.698737] NULL pointer dereference
[ 7685.705889]  at 0000000000000035
[ 7685.712357] IP: tcp_sacktag_walk+0xfd/0x460
[ 7685.720726] PGD 1002d75067 
[ 7685.726320] PUD 102c506067 
[ 7685.731902] PMD 0 
...
[ 7686.070541] task: ffff880ff5959b00 task.stack: ffffc90024708000
[ 7686.082363] RIP: 0010:tcp_sacktag_walk+0xfd/0x460
[ 7686.091754] RSP: 0000:ffff88203eec38b0 EFLAGS: 00010217
[ 7686.102188] RAX: ffff881953620a00 RBX: ffff881009273200 RCX: 00000000fbfa50ec
[ 7686.116439] RDX: 00000000fbfa54a0 RSI: 0000000000000000 RDI: ffff881009273200
[ 7686.130688] RBP: ffff88203eec3908 R08: 0000000000000048 R09: 00000000fbfa55fb
[ 7686.144936] R10: 0000000000000000 R11: 0000000000000000 R12: ffff881ec9ff98c0
[ 7686.159184] R13: ffff88203eec3a10 R14: 0000000000000000 R15: ffff881ec9ff9a18
[ 7686.173431] FS:  00007f2b235ff700(0000) GS:ffff88203eec0000(0000) knlGS:0000000000000000
[ 7686.189589] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 7686.201062] CR2: 0000000000000035 CR3: 0000000fd8229000 CR4: 00000000003406e0
[ 7686.215310] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 7686.229560] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 7686.243807] Call Trace:
[ 7686.248696]  <IRQ>
[ 7686.252727]  tcp_sacktag_write_queue+0x5ff/0x9e0
[ 7686.261943]  tcp_ack+0x677/0x1390
[ 7686.268569]  ? select_task_rq_fair+0x9e3/0xf70
[ 7686.277437]  ? tcp_write_xmit+0x230/0x10a0
[ 7686.285619]  tcp_rcv_established+0x1ce/0x740
[ 7686.294151]  tcp_v6_do_rcv+0x15b/0x400
[ 7686.301636]  tcp_v6_rcv+0x94c/0x9f0
[ 7686.308606]  ? default_wake_function+0x12/0x20
[ 7686.317483]  ? __wake_up_common+0x53/0x90
[ 7686.325492]  ip6_input_finish+0xea/0x430
[ 7686.333329]  ip6_input+0x32/0xa0
[ 7686.339791]  ? ip6_rcv_finish+0xa0/0xa0
[ 7686.347451]  ip6_rcv_finish+0x4b/0xa0
[ 7686.354767]  ipv6_rcv+0x2ec/0x4f0
[ 7686.361389]  ? ip6_make_skb+0x1c0/0x1c0
[ 7686.369050]  __netif_receive_skb_core+0x2d5/0x9a0
[ 7686.378449]  ? tcp6_gro_receive+0x11d/0x1c0
[ 7686.386797]  ? ipv6_gro_receive+0x1d0/0x380
[ 7686.395160]  __netif_receive_skb+0x16/0x70
[ 7686.403342]  netif_receive_skb_internal+0x32/0x3b0
[ 7686.412931]  ? dev_gro_receive+0x27c/0x470
[ 7686.421110]  napi_gro_receive+0x113/0x1d0
[ 7686.429136]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[ 7686.438722]  mlx5e_poll_rx_cq+0x79/0x830
[ 7686.446572]  mlx5e_napi_poll+0x8c/0x3d0
[ 7686.454233]  ? mlx5_cq_completion+0x54/0xb0
[ 7686.462591]  net_rx_action+0x22e/0x380
[ 7686.470099]  __do_softirq+0x106/0x2e8
[ 7686.477431]  irq_exit+0xb0/0xc0
[ 7686.483700]  do_IRQ+0x4f/0xd0
[ 7686.489629]  common_interrupt+0x86/0x86

Sometimes soft lockup is also seen:

[2676627.345885] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [swapper/0:0]
[2676627.717771] RIP: 0010:queued_spin_lock_slowpath+0x15c/0x180
[2676627.729239] RSP: 0018:ffff88103f603e78 EFLAGS: 00000202
[2676627.740019]  ORIG_RAX: ffffffffffffff10
[2676627.748027] RAX: 0000000000000101 RBX: ffff8811181d8840 RCX: 0000000000000101
[2676627.762622] RDX: 0000000000000101 RSI: 0000000000000001 RDI: ffff8811181d88c8
[2676627.777217] RBP: ffff88103f603e88 R08: 0000000000000001 R09: ffff88103f95a800
[2676627.791811] R10: 0000000000037a13 R11: 000000001a37bb20 R12: 0000000000000100
[2676627.806405] R13: ffff8811181d8c18 R14: ffffffff81857270 R15: ffff8811181d8840
[2676627.821000] FS:  0000000000000000(0000) GS:ffff88103f600000(0000) knlGS:0000000000000000
[2676627.837500] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[2676627.849318] CR2: 00007f6e44c1f000 CR3: 0000000001e09000 CR4: 00000000003406f0
[2676627.863916] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[2676627.878508] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[2676627.893103] Call Trace:
[2676627.898338]  <IRQ>
[2676627.902711]  ? _raw_spin_lock+0x21/0x30
[2676627.910715]  tcp_write_timer+0x19/0x70
[2676627.918548]  call_timer_fn+0x35/0x150
[2676627.926214]  run_timer_softirq+0x1be/0x3e0
[2676627.934742]  ? timerqueue_add+0x59/0xb0
[2676627.942745]  ? ktime_get+0x3c/0xb0
[2676627.949889]  __do_softirq+0x106/0x2e8
[2676627.957551]  irq_exit+0xb0/0xc0
[2676627.964174]  smp_apic_timer_interrupt+0x68/0x90
[2676627.973563]  apic_timer_interrupt+0x86/0x90
[2676628.084861] NMI watchdog: BUG: soft lockup - CPU#11 stuck for 21s! [swapper/11:0]
[2676628.084896] RIP: 0010:tcp_match_skb_to_sack+0x2d/0xb0
[2676628.084897] RSP: 0018:ffff88103f8c38a8 EFLAGS: 00000297
[2676628.084897]  ORIG_RAX: ffffffffffffff10
[2676628.084898] RAX: 0000000000000000 RBX: ffff88010f9dbb18 RCX: 000000002d5da350
[2676628.084899] RDX: 000000002d5da141 RSI: ffff88010f9dbb18 RDI: ffff8811181d8840
[2676628.084899] RBP: ffff88103f8c3908 R08: 00000000ffffffff R09: 00000000d2a25ebe
[2676628.084900] R10: 000000000000e323 R11: ffff8811181d8998 R12: ffff8811181d8840
[2676628.084900] R13: ffff88103f8c3a10 R14: 0000000000000000 R15: ffff8811181d8998
[2676628.084901] FS:  0000000000000000(0000) GS:ffff88103f8c0000(0000) knlGS:0000000000000000
[2676628.084902] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[2676628.084903] CR2: 00007fbc07410000 CR3: 0000000001e09000 CR4: 00000000003406e0
[2676628.084903] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[2676628.084904] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[2676628.084904] Call Trace:
[2676628.084905]  <IRQ>
[2676628.084907]  ? tcp_sacktag_walk+0x270/0x460
[2676628.084909]  tcp_sacktag_write_queue+0x5ff/0x9e0
[2676628.084911]  tcp_ack+0x677/0x1390
[2676628.084913]  ? tcp_write_xmit+0x230/0x10a0
[2676628.084915]  tcp_rcv_established+0x1ce/0x740
[2676628.084919]  tcp_v6_do_rcv+0x15b/0x400
[2676628.084921]  tcp_v6_rcv+0x94c/0x9f0
[2676628.084924]  ? __dev_queue_xmit+0x251/0x650
[2676628.084928]  ip6_input_finish+0xea/0x430
[2676628.084930]  ip6_input+0x32/0xa0
[2676628.084932]  ? ip6_rcv_finish+0xa0/0xa0
[2676628.084933]  ip6_rcv_finish+0x4b/0xa0
[2676628.084935]  ipv6_rcv+0x2ec/0x4f0
[2676628.084937]  ? ip6_make_skb+0x1c0/0x1c0
[2676628.084938]  __netif_receive_skb_core+0x2d5/0x9a0
[2676628.084941]  ? tcp6_gro_receive+0x11d/0x1c0
[2676628.084943]  ? ipv6_gro_receive+0x1d0/0x380
[2676628.084944]  __netif_receive_skb+0x16/0x70
[2676628.084945]  netif_receive_skb_internal+0x32/0x3b0
[2676628.084947]  ? dev_gro_receive+0x27c/0x470
[2676628.084948]  napi_gro_receive+0x113/0x1d0
[2676628.084952]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[2676628.084954]  mlx5e_poll_rx_cq+0x79/0x830
[2676628.084956]  mlx5e_napi_poll+0x8c/0x3d0
[2676628.084959]  ? mlx5_cq_completion+0x54/0xb0
[2676628.084960]  net_rx_action+0x22e/0x380
[2676628.084962]  __do_softirq+0x106/0x2e8
[2676628.084965]  irq_exit+0xb0/0xc0
[2676628.084967]  do_IRQ+0x4f/0xd0
[2676656.083964] NMI watchdog: BUG: soft lockup - CPU#11 stuck for 23s! [swapper/11:0]
[2676656.083992] RIP: 0010:tcp_sacktag_walk+0x25f/0x460
[2676656.083993] RSP: 0018:ffff88103f8c38b0 EFLAGS: 00000207
[2676656.083993]  ORIG_RAX: ffffffffffffff10
[2676656.083994] RAX: 0000000000021500 RBX: ffff8810d84c3600 RCX: 000000002d5d9e41
[2676656.083994] RDX: 00000000f15de229 RSI: ffff8810d84c0200 RDI: ffff8811181d8840
[2676656.083995] RBP: ffff88103f8c3908 R08: 000000000000ff21 R09: 0000000000000000
[2676656.083996] R10: 000000000000e323 R11: ffff8811181d8998 R12: ffff8811181d8840
[2676656.083996] R13: ffff88103f8c3a10 R14: 0000000000000000 R15: ffff8811181d8998
[2676656.083997] FS:  0000000000000000(0000) GS:ffff88103f8c0000(0000) knlGS:0000000000000000
[2676656.083998] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[2676656.083998] CR2: 00007fbc07410000 CR3: 0000000001e09000 CR4: 00000000003406e0
[2676656.083999] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[2676656.083999] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[2676656.084000] Call Trace:
[2676656.084001]  <IRQ>
[2676656.084003]  tcp_sacktag_write_queue+0x5ff/0x9e0
[2676656.084005]  tcp_ack+0x677/0x1390
[2676656.084007]  ? tcp_write_xmit+0x230/0x10a0
[2676656.084009]  tcp_rcv_established+0x1ce/0x740
[2676656.084013]  tcp_v6_do_rcv+0x15b/0x400
[2676656.084015]  tcp_v6_rcv+0x94c/0x9f0
[2676656.084018]  ? __dev_queue_xmit+0x251/0x650
[2676656.084022]  ip6_input_finish+0xea/0x430
[2676656.084024]  ip6_input+0x32/0xa0
[2676656.084026]  ? ip6_rcv_finish+0xa0/0xa0
[2676656.084027]  ip6_rcv_finish+0x4b/0xa0
[2676656.084029]  ipv6_rcv+0x2ec/0x4f0
[2676656.084031]  ? ip6_make_skb+0x1c0/0x1c0
[2676656.084032]  __netif_receive_skb_core+0x2d5/0x9a0
[2676656.084035]  ? tcp6_gro_receive+0x11d/0x1c0
[2676656.084037]  ? ipv6_gro_receive+0x1d0/0x380
[2676656.084038]  __netif_receive_skb+0x16/0x70
[2676656.084039]  netif_receive_skb_internal+0x32/0x3b0
[2676656.084041]  ? dev_gro_receive+0x27c/0x470
[2676656.084042]  napi_gro_receive+0x113/0x1d0
[2676656.084046]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[2676656.084048]  mlx5e_poll_rx_cq+0x79/0x830
[2676656.084050]  mlx5e_napi_poll+0x8c/0x3d0

Any help greatly appreciated.

On Wed, Oct 25, 2017 at 7:07 PM, Alexei Starovoitov
[off-list ref] wrote:

On Thu, Sep 28, 2017 at 04:36:58PM -0700, Yuchung Cheng wrote:

quoted

On Thu, Sep 28, 2017 at 1:14 AM, Oleksandr Natalenko
[off-list ref] wrote:

quoted

Hi.

Won't tell about panic in tcp_sacktag_walk() since I cannot trigger it
intentionally, but setting net.ipv4.tcp_retrans_collapse to 0 *does not* fix
warning in tcp_fastretrans_alert() for me.

Hi Oleksandr: no retrans_collapse should not matter for that warning
in tcp_fstretrans_alert(). the warning as I explained earlier is
likely false. Neal and I are more concerned the panic in
tcp_sacktag_walk. This is just a blind shot but thx for retrying.

We can submit a one-liner to remove the fast retrans warning but want
to nail the bigger issue first.

we're still seeing the warnings followed by crashes and it's very concerning.
We hoped that most recent Neal's patches from Sep 18 around this area may
magically fix the issue, but no. The panics are still there.
It's confirmed that net.ipv4.tcp_retrans_collapse=0 does not help
whereas net.ipv4.tcp_recovery=0 works, but obviously undesirable.
We're out of ideas on how to debug this.

Can you try Eric's latest SACK rb-tree patches?
https://patchwork.ozlabs.org/cover/822218/

Roman's SNMP data suggests MTU probing is enabled. Another blind shot
is to disable it.

Warning + panic:
[ 7678.309043] Call Trace:
[ 7678.313925]  <IRQ>
[ 7678.317955]  dump_stack+0x4d/0x70
[ 7678.324573]  __warn+0xd3/0xf0
[ 7678.330497]  warn_slowpath_null+0x1e/0x20
[ 7678.338510]  tcp_fastretrans_alert+0xacf/0xbd0
[ 7678.347380]  tcp_ack+0xbce/0x1390
[ 7678.354006]  tcp_rcv_established+0x1ce/0x740
[ 7678.362536]  tcp_v6_do_rcv+0x15b/0x400
[ 7678.370025]  tcp_v6_rcv+0x94c/0x9f0
[ 7678.376989]  ? tcp_rcv_established+0x42b/0x740
[ 7678.385866]  ip6_input_finish+0xea/0x430
[ 7678.393702]  ip6_input+0x32/0xa0
[ 7678.400155]  ? ip6_rcv_finish+0xa0/0xa0
[ 7678.407834]  ip6_rcv_finish+0x4b/0xa0
[ 7678.415164]  ipv6_rcv+0x2ec/0x4f0
[ 7678.421778]  ? ip6_make_skb+0x1c0/0x1c0
[ 7678.429447]  __netif_receive_skb_core+0x2d5/0x9a0
[ 7678.438845]  ? tcp6_gro_receive+0x11d/0x1c0
[ 7678.447211]  ? ipv6_gro_receive+0x1d0/0x380
[ 7678.455566]  __netif_receive_skb+0x16/0x70
[ 7678.463748]  netif_receive_skb_internal+0x32/0x3b0
[ 7678.473318]  ? dev_gro_receive+0x27c/0x470
[ 7678.481502]  napi_gro_receive+0x113/0x1d0
[ 7678.489510]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[ 7678.499077]  mlx5e_poll_rx_cq+0x79/0x830
[ 7678.506911]  mlx5e_napi_poll+0x8c/0x3d0
[ 7678.514579]  ? mlx5_cq_completion+0x54/0xb0
[ 7678.522950]  net_rx_action+0x22e/0x380
[ 7678.530450]  __do_softirq+0x106/0x2e8
[ 7678.537768]  irq_exit+0xb0/0xc0
[ 7678.544042]  do_IRQ+0x4f/0xd0
[ 7678.549970]  common_interrupt+0x86/0x86
...
[ 7685.690697] BUG: unable to handle kernel
[ 7685.698737] NULL pointer dereference
[ 7685.705889]  at 0000000000000035
[ 7685.712357] IP: tcp_sacktag_walk+0xfd/0x460
[ 7685.720726] PGD 1002d75067
[ 7685.726320] PUD 102c506067
[ 7685.731902] PMD 0
...
[ 7686.070541] task: ffff880ff5959b00 task.stack: ffffc90024708000
[ 7686.082363] RIP: 0010:tcp_sacktag_walk+0xfd/0x460
[ 7686.091754] RSP: 0000:ffff88203eec38b0 EFLAGS: 00010217
[ 7686.102188] RAX: ffff881953620a00 RBX: ffff881009273200 RCX: 00000000fbfa50ec
[ 7686.116439] RDX: 00000000fbfa54a0 RSI: 0000000000000000 RDI: ffff881009273200
[ 7686.130688] RBP: ffff88203eec3908 R08: 0000000000000048 R09: 00000000fbfa55fb
[ 7686.144936] R10: 0000000000000000 R11: 0000000000000000 R12: ffff881ec9ff98c0
[ 7686.159184] R13: ffff88203eec3a10 R14: 0000000000000000 R15: ffff881ec9ff9a18
[ 7686.173431] FS:  00007f2b235ff700(0000) GS:ffff88203eec0000(0000) knlGS:0000000000000000
[ 7686.189589] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 7686.201062] CR2: 0000000000000035 CR3: 0000000fd8229000 CR4: 00000000003406e0
[ 7686.215310] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 7686.229560] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 7686.243807] Call Trace:
[ 7686.248696]  <IRQ>
[ 7686.252727]  tcp_sacktag_write_queue+0x5ff/0x9e0
[ 7686.261943]  tcp_ack+0x677/0x1390
[ 7686.268569]  ? select_task_rq_fair+0x9e3/0xf70
[ 7686.277437]  ? tcp_write_xmit+0x230/0x10a0
[ 7686.285619]  tcp_rcv_established+0x1ce/0x740
[ 7686.294151]  tcp_v6_do_rcv+0x15b/0x400
[ 7686.301636]  tcp_v6_rcv+0x94c/0x9f0
[ 7686.308606]  ? default_wake_function+0x12/0x20
[ 7686.317483]  ? __wake_up_common+0x53/0x90
[ 7686.325492]  ip6_input_finish+0xea/0x430
[ 7686.333329]  ip6_input+0x32/0xa0
[ 7686.339791]  ? ip6_rcv_finish+0xa0/0xa0
[ 7686.347451]  ip6_rcv_finish+0x4b/0xa0
[ 7686.354767]  ipv6_rcv+0x2ec/0x4f0
[ 7686.361389]  ? ip6_make_skb+0x1c0/0x1c0
[ 7686.369050]  __netif_receive_skb_core+0x2d5/0x9a0
[ 7686.378449]  ? tcp6_gro_receive+0x11d/0x1c0
[ 7686.386797]  ? ipv6_gro_receive+0x1d0/0x380
[ 7686.395160]  __netif_receive_skb+0x16/0x70
[ 7686.403342]  netif_receive_skb_internal+0x32/0x3b0
[ 7686.412931]  ? dev_gro_receive+0x27c/0x470
[ 7686.421110]  napi_gro_receive+0x113/0x1d0
[ 7686.429136]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[ 7686.438722]  mlx5e_poll_rx_cq+0x79/0x830
[ 7686.446572]  mlx5e_napi_poll+0x8c/0x3d0
[ 7686.454233]  ? mlx5_cq_completion+0x54/0xb0
[ 7686.462591]  net_rx_action+0x22e/0x380
[ 7686.470099]  __do_softirq+0x106/0x2e8
[ 7686.477431]  irq_exit+0xb0/0xc0
[ 7686.483700]  do_IRQ+0x4f/0xd0
[ 7686.489629]  common_interrupt+0x86/0x86

Sometimes soft lockup is also seen:

[2676627.345885] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [swapper/0:0]
[2676627.717771] RIP: 0010:queued_spin_lock_slowpath+0x15c/0x180
[2676627.729239] RSP: 0018:ffff88103f603e78 EFLAGS: 00000202
[2676627.740019]  ORIG_RAX: ffffffffffffff10
[2676627.748027] RAX: 0000000000000101 RBX: ffff8811181d8840 RCX: 0000000000000101
[2676627.762622] RDX: 0000000000000101 RSI: 0000000000000001 RDI: ffff8811181d88c8
[2676627.777217] RBP: ffff88103f603e88 R08: 0000000000000001 R09: ffff88103f95a800
[2676627.791811] R10: 0000000000037a13 R11: 000000001a37bb20 R12: 0000000000000100
[2676627.806405] R13: ffff8811181d8c18 R14: ffffffff81857270 R15: ffff8811181d8840
[2676627.821000] FS:  0000000000000000(0000) GS:ffff88103f600000(0000) knlGS:0000000000000000
[2676627.837500] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[2676627.849318] CR2: 00007f6e44c1f000 CR3: 0000000001e09000 CR4: 00000000003406f0
[2676627.863916] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[2676627.878508] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[2676627.893103] Call Trace:
[2676627.898338]  <IRQ>
[2676627.902711]  ? _raw_spin_lock+0x21/0x30
[2676627.910715]  tcp_write_timer+0x19/0x70
[2676627.918548]  call_timer_fn+0x35/0x150
[2676627.926214]  run_timer_softirq+0x1be/0x3e0
[2676627.934742]  ? timerqueue_add+0x59/0xb0
[2676627.942745]  ? ktime_get+0x3c/0xb0
[2676627.949889]  __do_softirq+0x106/0x2e8
[2676627.957551]  irq_exit+0xb0/0xc0
[2676627.964174]  smp_apic_timer_interrupt+0x68/0x90
[2676627.973563]  apic_timer_interrupt+0x86/0x90
[2676628.084861] NMI watchdog: BUG: soft lockup - CPU#11 stuck for 21s! [swapper/11:0]
[2676628.084896] RIP: 0010:tcp_match_skb_to_sack+0x2d/0xb0
[2676628.084897] RSP: 0018:ffff88103f8c38a8 EFLAGS: 00000297
[2676628.084897]  ORIG_RAX: ffffffffffffff10
[2676628.084898] RAX: 0000000000000000 RBX: ffff88010f9dbb18 RCX: 000000002d5da350
[2676628.084899] RDX: 000000002d5da141 RSI: ffff88010f9dbb18 RDI: ffff8811181d8840
[2676628.084899] RBP: ffff88103f8c3908 R08: 00000000ffffffff R09: 00000000d2a25ebe
[2676628.084900] R10: 000000000000e323 R11: ffff8811181d8998 R12: ffff8811181d8840
[2676628.084900] R13: ffff88103f8c3a10 R14: 0000000000000000 R15: ffff8811181d8998
[2676628.084901] FS:  0000000000000000(0000) GS:ffff88103f8c0000(0000) knlGS:0000000000000000
[2676628.084902] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[2676628.084903] CR2: 00007fbc07410000 CR3: 0000000001e09000 CR4: 00000000003406e0
[2676628.084903] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[2676628.084904] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[2676628.084904] Call Trace:
[2676628.084905]  <IRQ>
[2676628.084907]  ? tcp_sacktag_walk+0x270/0x460
[2676628.084909]  tcp_sacktag_write_queue+0x5ff/0x9e0
[2676628.084911]  tcp_ack+0x677/0x1390
[2676628.084913]  ? tcp_write_xmit+0x230/0x10a0
[2676628.084915]  tcp_rcv_established+0x1ce/0x740
[2676628.084919]  tcp_v6_do_rcv+0x15b/0x400
[2676628.084921]  tcp_v6_rcv+0x94c/0x9f0
[2676628.084924]  ? __dev_queue_xmit+0x251/0x650
[2676628.084928]  ip6_input_finish+0xea/0x430
[2676628.084930]  ip6_input+0x32/0xa0
[2676628.084932]  ? ip6_rcv_finish+0xa0/0xa0
[2676628.084933]  ip6_rcv_finish+0x4b/0xa0
[2676628.084935]  ipv6_rcv+0x2ec/0x4f0
[2676628.084937]  ? ip6_make_skb+0x1c0/0x1c0
[2676628.084938]  __netif_receive_skb_core+0x2d5/0x9a0
[2676628.084941]  ? tcp6_gro_receive+0x11d/0x1c0
[2676628.084943]  ? ipv6_gro_receive+0x1d0/0x380
[2676628.084944]  __netif_receive_skb+0x16/0x70
[2676628.084945]  netif_receive_skb_internal+0x32/0x3b0
[2676628.084947]  ? dev_gro_receive+0x27c/0x470
[2676628.084948]  napi_gro_receive+0x113/0x1d0
[2676628.084952]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[2676628.084954]  mlx5e_poll_rx_cq+0x79/0x830
[2676628.084956]  mlx5e_napi_poll+0x8c/0x3d0
[2676628.084959]  ? mlx5_cq_completion+0x54/0xb0
[2676628.084960]  net_rx_action+0x22e/0x380
[2676628.084962]  __do_softirq+0x106/0x2e8
[2676628.084965]  irq_exit+0xb0/0xc0
[2676628.084967]  do_IRQ+0x4f/0xd0
[2676656.083964] NMI watchdog: BUG: soft lockup - CPU#11 stuck for 23s! [swapper/11:0]
[2676656.083992] RIP: 0010:tcp_sacktag_walk+0x25f/0x460
[2676656.083993] RSP: 0018:ffff88103f8c38b0 EFLAGS: 00000207
[2676656.083993]  ORIG_RAX: ffffffffffffff10
[2676656.083994] RAX: 0000000000021500 RBX: ffff8810d84c3600 RCX: 000000002d5d9e41
[2676656.083994] RDX: 00000000f15de229 RSI: ffff8810d84c0200 RDI: ffff8811181d8840
[2676656.083995] RBP: ffff88103f8c3908 R08: 000000000000ff21 R09: 0000000000000000
[2676656.083996] R10: 000000000000e323 R11: ffff8811181d8998 R12: ffff8811181d8840
[2676656.083996] R13: ffff88103f8c3a10 R14: 0000000000000000 R15: ffff8811181d8998
[2676656.083997] FS:  0000000000000000(0000) GS:ffff88103f8c0000(0000) knlGS:0000000000000000
[2676656.083998] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[2676656.083998] CR2: 00007fbc07410000 CR3: 0000000001e09000 CR4: 00000000003406e0
[2676656.083999] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[2676656.083999] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[2676656.084000] Call Trace:
[2676656.084001]  <IRQ>
[2676656.084003]  tcp_sacktag_write_queue+0x5ff/0x9e0
[2676656.084005]  tcp_ack+0x677/0x1390
[2676656.084007]  ? tcp_write_xmit+0x230/0x10a0
[2676656.084009]  tcp_rcv_established+0x1ce/0x740
[2676656.084013]  tcp_v6_do_rcv+0x15b/0x400
[2676656.084015]  tcp_v6_rcv+0x94c/0x9f0
[2676656.084018]  ? __dev_queue_xmit+0x251/0x650
[2676656.084022]  ip6_input_finish+0xea/0x430
[2676656.084024]  ip6_input+0x32/0xa0
[2676656.084026]  ? ip6_rcv_finish+0xa0/0xa0
[2676656.084027]  ip6_rcv_finish+0x4b/0xa0
[2676656.084029]  ipv6_rcv+0x2ec/0x4f0
[2676656.084031]  ? ip6_make_skb+0x1c0/0x1c0
[2676656.084032]  __netif_receive_skb_core+0x2d5/0x9a0
[2676656.084035]  ? tcp6_gro_receive+0x11d/0x1c0
[2676656.084037]  ? ipv6_gro_receive+0x1d0/0x380
[2676656.084038]  __netif_receive_skb+0x16/0x70
[2676656.084039]  netif_receive_skb_internal+0x32/0x3b0
[2676656.084041]  ? dev_gro_receive+0x27c/0x470
[2676656.084042]  napi_gro_receive+0x113/0x1d0
[2676656.084046]  mlx5e_handle_rx_cqe_mpwrq+0x5b6/0x8d0
[2676656.084048]  mlx5e_poll_rx_cq+0x79/0x830
[2676656.084050]  mlx5e_napi_poll+0x8c/0x3d0

Any help greatly appreciated.

On Wed, Oct 25, 2017 at 10:37 PM, Yuchung Cheng [off-list ref] wrote:

On Wed, Oct 25, 2017 at 7:07 PM, Alexei Starovoitov
[off-list ref] wrote:

quoted

On Thu, Sep 28, 2017 at 04:36:58PM -0700, Yuchung Cheng wrote:

quoted

On Thu, Sep 28, 2017 at 1:14 AM, Oleksandr Natalenko
[off-list ref] wrote:

quoted

Hi.

Won't tell about panic in tcp_sacktag_walk() since I cannot trigger it
intentionally, but setting net.ipv4.tcp_retrans_collapse to 0 *does not* fix
warning in tcp_fastretrans_alert() for me.

Hi Oleksandr: no retrans_collapse should not matter for that warning
in tcp_fstretrans_alert(). the warning as I explained earlier is
likely false. Neal and I are more concerned the panic in
tcp_sacktag_walk. This is just a blind shot but thx for retrying.

We can submit a one-liner to remove the fast retrans warning but want
to nail the bigger issue first.

we're still seeing the warnings followed by crashes and it's very concerning.
We hoped that most recent Neal's patches from Sep 18 around this area may
magically fix the issue, but no. The panics are still there.
It's confirmed that net.ipv4.tcp_retrans_collapse=0 does not help
whereas net.ipv4.tcp_recovery=0 works, but obviously undesirable.
We're out of ideas on how to debug this.

Can you try Eric's latest SACK rb-tree patches?
https://patchwork.ozlabs.org/cover/822218/

Roman's SNMP data suggests MTU probing is enabled. Another blind shot
is to disable it.

Or alternatively try this fix :

diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
index 1151870018e345592853b035a0902121c41e268d..6a849c7028f06f31b36a906be37995b28b579a40

100644

--- a/net/ipv4/tcp_output.c
+++ b/net/ipv4/tcp_output.c

@@ -2062,6 +2062,8 @@ static int tcp_mtu_probe(struct sock *sk)
        nskb->ip_summed = skb->ip_summed;

        tcp_insert_write_queue_before(nskb, skb, sk);
+       if (skb == tp->highest_sack)
+               tp->highest_sack = nskb;

        len = 0;
        tcp_for_write_queue_from_safe(skb, next, sk) {

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>
---
 include/net/tcp.h     |    6 +++---
 net/ipv4/tcp_output.c |    3 ++-
 2 files changed, 5 insertions(+), 4 deletions(-)

diff --git a/include/net/tcp.h b/include/net/tcp.h
index 33599d17522d6a19b9d9a316cc1579cd5e71ee32..e6d0002a1b0bc5f28c331a760823c8dc92f8fe24 100644
--- a/include/net/tcp.h
+++ b/include/net/tcp.h

@@ -1771,12 +1771,12 @@ static inline void tcp_highest_sack_reset(struct sock *sk)
 	tcp_sk(sk)->highest_sack = tcp_write_queue_head(sk);
 }
 
-/* Called when old skb is about to be deleted (to be combined with new skb) */
-static inline void tcp_highest_sack_combine(struct sock *sk,
+/* Called when old skb is about to be deleted and replaced by new skb */
+static inline void tcp_highest_sack_replace(struct sock *sk,
 					    struct sk_buff *old,
 					    struct sk_buff *new)
 {
-	if (tcp_sk(sk)->sacked_out && (old == tcp_sk(sk)->highest_sack))
+	if (old == tcp_highest_sack(sk))
 		tcp_sk(sk)->highest_sack = new;
 }
 

diff --git a/net/ipv4/tcp_output.c b/net/ipv4/tcp_output.c
index ae60dd3faed0adc71731bc686f878afd4c628d32..823003eef3a21a5cc5c27e0be9f46159afa060df 100644
--- a/net/ipv4/tcp_output.c
+++ b/net/ipv4/tcp_output.c

@@ -2062,6 +2062,7 @@ static int tcp_mtu_probe(struct sock *sk)
 	nskb->ip_summed = skb->ip_summed;
 
 	tcp_insert_write_queue_before(nskb, skb, sk);
+	tcp_highest_sack_replace(sk, skb, nskb);
 
 	len = 0;
 	tcp_for_write_queue_from_safe(skb, next, sk) {

@@ -2665,7 +2666,7 @@ static bool tcp_collapse_retrans(struct sock *sk, struct sk_buff *skb)
 		else if (!skb_shift(skb, next_skb, next_skb_size))
 			return false;
 	}
-	tcp_highest_sack_combine(sk, next_skb, skb);
+	tcp_highest_sack_replace(sk, next_skb, skb);
 
 	tcp_unlink_write_queue(next_skb, sk);
 

On Mon, Oct 30, 2017 at 11:08:20PM -0700, Eric Dumazet wrote:

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>

Thanks!

Acked-by: Alexei Starovoitov <ast@kernel.org>

wow. a bug from 2007.
Any idea why it only started to bite us in 4.11 ?

It's not trivial for us to reproduce it, but we will definitely
test the patch as soon as we can.
Do you have packet drill test or something for easy repro?

On Mon, 2017-10-30 at 23:17 -0700, Alexei Starovoitov wrote:

On Mon, Oct 30, 2017 at 11:08:20PM -0700, Eric Dumazet wrote:

quoted

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>

Thanks!

Acked-by: Alexei Starovoitov <ast@kernel.org>

wow. a bug from 2007.
Any idea why it only started to bite us in 4.11 ?

It's not trivial for us to reproduce it, but we will definitely
test the patch as soon as we can.
Do you have packet drill test or something for easy repro?

I tried to cook a packetdrill test but could not trigger the issue.

When have you started to enable mtu probing ?

(Linux defaults to not enabling it )

On Mon, Oct 30, 2017 at 11:21:42PM -0700, Eric Dumazet wrote:

On Mon, 2017-10-30 at 23:17 -0700, Alexei Starovoitov wrote:

quoted

On Mon, Oct 30, 2017 at 11:08:20PM -0700, Eric Dumazet wrote:

quoted

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>

Thanks!

Acked-by: Alexei Starovoitov <ast@kernel.org>

wow. a bug from 2007.
Any idea why it only started to bite us in 4.11 ?

It's not trivial for us to reproduce it, but we will definitely
test the patch as soon as we can.
Do you have packet drill test or something for easy repro?

I tried to cook a packetdrill test but could not trigger the issue.

When have you started to enable mtu probing ?

for some time. somehow 4.6 based kernel didn't trigger it.
May be it's a different bug still...

On Tue, Oct 31, 2017 at 2:08 AM, Eric Dumazet [off-list ref] wrote:

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>
---
 include/net/tcp.h     |    6 +++---
 net/ipv4/tcp_output.c |    3 ++-
 2 files changed, 5 insertions(+), 4 deletions(-)

Acked-by: Neal Cardwell <ncardwell@google.com>

Nice catch, indeed. Thanks, Eric!

neal

On Mon, Oct 30, 2017 at 11:17 PM, Alexei Starovoitov
[off-list ref] wrote:

On Mon, Oct 30, 2017 at 11:08:20PM -0700, Eric Dumazet wrote:

quoted

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>

Thanks!

Acked-by: Alexei Starovoitov <ast@kernel.org>

wow. a bug from 2007.
Any idea why it only started to bite us in 4.11 ?

FWIW some random guess:
Since RACK was confirmed to trigger the issue, and RACK enables
detecting lost retransmission w/o limited-transmit in CA_Loss state, I
guess RACK create a new type of "fast retransmit" that caused some
previously impossible SACK during MTU probing.

Acked-by: Yuchung Cheng <redacted>

It's not trivial for us to reproduce it, but we will definitely
test the patch as soon as we can.
Do you have packet drill test or something for easy repro?

From: Eric Dumazet <redacted>
Date: Mon, 30 Oct 2017 23:08:20 -0700

From: Eric Dumazet <edumazet@google.com>

Based on SNMP values provided by Roman, Yuchung made the observation
that some crashes in tcp_sacktag_walk() might be caused by MTU probing.

Looking at tcp_mtu_probe(), I found that when a new skb was placed
in front of the write queue, we were not updating tcp highest sack.

If one skb is freed because all its content was copied to the new skb
(for MTU probing), then tp->highest_sack could point to a now freed skb.

Bad things would then happen, including infinite loops.

This patch renames tcp_highest_sack_combine() and uses it
from tcp_mtu_probe() to fix the bug.

Note that I also removed one test against tp->sacked_out,
since we want to replace tp->highest_sack regardless of whatever
condition, since keeping a stale pointer to freed skb is a recipe
for disaster.

Fixes: a47e5a988a57 ("[TCP]: Convert highest_sack to sk_buff to allow direct access")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Alexei Starovoitov <redacted>
Reported-by: Roman Gushchin <redacted>
Reported-by: Oleksandr Natalenko <redacted>

Applied and queued up for -stable.

Hi.

Thanks for the fix.

However, tcp_fastretrans_alert() warning case still remains open even with 
this patch. Do I understand correctly that these are 2 different issues?

Currently, I use latest 4.13 stable kernel + this patch and still get:

WARNING: CPU: 1 PID: 736 at net/ipv4/tcp_input.c:2826 tcp_fastretrans_alert
+0x7c8/0x990

Any idea on this?

On úterý 31. října 2017 7:08:20 CET Eric Dumazet wrote:

On Fri, 2017-11-03 at 19:22 +0100, Oleksandr Natalenko wrote:

Hi.

Thanks for the fix.

However, tcp_fastretrans_alert() warning case still remains open even with 
this patch. Do I understand correctly that these are 2 different issues?

Currently, I use latest 4.13 stable kernel + this patch and still get:

WARNING: CPU: 1 PID: 736 at net/ipv4/tcp_input.c:2826 tcp_fastretrans_alert
+0x7c8/

My patch only fixed the panics that you guys reported.

The warning issue in fastretrans is a separate problem,
we are still working on it, but at least the effects are not
catastrophic.

On Fri, Oct 27, 2017 at 1:38 PM, Eric Dumazet [off-list ref] wrote:

On Wed, Oct 25, 2017 at 10:37 PM, Yuchung Cheng [off-list ref] wrote:

quoted

On Wed, Oct 25, 2017 at 7:07 PM, Alexei Starovoitov
[off-list ref] wrote:

quoted

On Thu, Sep 28, 2017 at 04:36:58PM -0700, Yuchung Cheng wrote:

quoted

On Thu, Sep 28, 2017 at 1:14 AM, Oleksandr Natalenko
[off-list ref] wrote:

quoted

Hi.

Won't tell about panic in tcp_sacktag_walk() since I cannot trigger it
intentionally, but setting net.ipv4.tcp_retrans_collapse to 0 *does not* fix
warning in tcp_fastretrans_alert() for me.

Hi Oleksandr: no retrans_collapse should not matter for that warning
in tcp_fstretrans_alert(). the warning as I explained earlier is

hi guys can you try if the warning goes away w/ this quick fix?

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
index 0ada8bfc2ebd..072aab2a8226 100644
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c

@@ -2626,7 +2626,7 @@ void tcp_simple_retransmit(struct sock *sk)

        tcp_clear_retrans_hints_partial(tp);

-       if (prior_lost == tp->lost_out)
+       if (!tp->lost_out)
                return;

        if (tcp_is_reno(tp))

Hi.

I'm running the machine with this patch applied for 7 hours now, and the 
warning hasn't appeared yet. Typically, it should be there within the 
first hour.

I'll keep an eye on it for a longer time, but as of now it looks good.

Some explanation on this please?

Thanks!

06.11.2017 23:27, Yuchung Cheng wrote:
...snip...

...snip...

Uhh, sorry, just found the original submission [1].

[1] https://marc.info/?l=linux-netdev&m=151009763926816&w=2

10.11.2017 14:15, Oleksandr Natalenko wrote:

Hi.

I'm running the machine with this patch applied for 7 hours now, and
the warning hasn't appeared yet. Typically, it should be there within
the first hour.

I'll keep an eye on it for a longer time, but as of now it looks good.

Some explanation on this please?

Thanks!

06.11.2017 23:27, Yuchung Cheng wrote:
...snip...

quoted

hi guys can you try if the warning goes away w/ this quick fix?

diff --git a/net/ipv4/tcp_input.c b/net/ipv4/tcp_input.c
index 0ada8bfc2ebd..072aab2a8226 100644
--- a/net/ipv4/tcp_input.c
+++ b/net/ipv4/tcp_input.c

@@ -2626,7 +2626,7 @@ void tcp_simple_retransmit(struct sock *sk)

        tcp_clear_retrans_hints_partial(tp);

-       if (prior_lost == tp->lost_out)
+       if (!tp->lost_out)
                return;

        if (tcp_is_reno(tp))

...snip...