lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <83e6f799-98a8-da7d-512d-e9ffb6eb55fe@meta.com>
Date:   Tue, 24 Jan 2023 15:09:55 +0000
From:   Vadim Fedorenko <vadfed@...a.com>
To:     Gal Pressman <gal@...dia.com>
CC:     "netdev@...r.kernel.org" <netdev@...r.kernel.org>,
        Aya Levin <ayal@...dia.com>,
        Saeed Mahameed <saeedm@...dia.com>,
        Jakub Kicinski <kuba@...nel.org>
Subject: Re: [PATCH net 1/2] mlx5: fix possible ptp queue fifo overflow

On 24/01/2023 14:39, Gal Pressman wrote:
> On 23/01/2023 19:24, Vadim Fedorenko wrote:
>>   > Hi Vadim,
>>   >
>>
>> Hi Gal!
>> Your mail didn't show up in my mailbox for some reasons, so I tried to
>> construct it back from mailing list. This may end up with some side
>> effects, but I did my best to avoid it.
>>
>>   > On 22/01/2023 18:16, Vadim Fedorenko wrote:
>>   >> Fifo pointers are not checked for overflow and this could potentially
>>   >> lead to overflow and double free under heavy PTP traffic.
>>   >>
>>   >> Also there were accidental OOO cqe which lead to absolutely broken fifo.
>>   >> Add checks to workaround OOO cqe and add counters to show the amount of
>>   >> such events.
>>   >>
>>   >> Fixes: 19b43a432e3e ("net/mlx5e: Extend SKB room check to include
>> PTP-SQ")
>>   >
>>   > Isn't 58a518948f60 ("net/mlx5e: Add resiliency for PTP TX port
>>   > timestamp") more appropriate?
>>
>> It looks like the bugs were actually introduced by the commit in Fixes
>> even though the commit you mentioned introduced the feature itself. But
>> I might be wrong, I'll recheck it.
>>
>>   >> Signed-off-by: Vadim Fedorenko <vadfed@...a.com>
>>   >> ---
>>   >>  .../net/ethernet/mellanox/mlx5/core/en/ptp.c  | 28 ++++++++++++++-----
>>   >>  .../net/ethernet/mellanox/mlx5/core/en/txrx.h |  6 +++-
>>   >>  .../ethernet/mellanox/mlx5/core/en_stats.c    |  2 ++
>>   >>  .../ethernet/mellanox/mlx5/core/en_stats.h    |  2 ++
>>   >>  4 files changed, 30 insertions(+), 8 deletions(-)
>>   >>
>>   >> diff --git a/drivers/net/ethernet/mellanox/mlx5/core/en/ptp.c
>> b/drivers/net/ethernet/mellanox/mlx5/core/en/ptp.c
>>   >> index 903de88bab53..11a99e0f00c6 100644
>>   >> --- a/drivers/net/ethernet/mellanox/mlx5/core/en/ptp.c
>>   >> +++ b/drivers/net/ethernet/mellanox/mlx5/core/en/ptp.c
>>   >> @@ -86,20 +86,31 @@ static bool mlx5e_ptp_ts_cqe_drop(struct
>> mlx5e_ptpsq *ptpsq, u16 skb_cc, u16 skb
>>   >>  	return (ptpsq->ts_cqe_ctr_mask && (skb_cc != skb_id));
>>   >>  }
>>   >>
>>   >> -static void mlx5e_ptp_skb_fifo_ts_cqe_resync(struct mlx5e_ptpsq
>> *ptpsq, u16 skb_cc, u16 skb_id)
>>   >> +static bool mlx5e_ptp_skb_fifo_ts_cqe_resync(struct mlx5e_ptpsq
>> *ptpsq, u16 skb_cc, u16 skb_id)
>>   >>  {
>>   >>  	struct skb_shared_hwtstamps hwts = {};
>>   >>  	struct sk_buff *skb;
>>   >>
>>   >>  	ptpsq->cq_stats->resync_event++;
>>   >>
>>   >> -	while (skb_cc != skb_id) {
>>   >> -		skb = mlx5e_skb_fifo_pop(&ptpsq->skb_fifo);
>>   >> +	if (skb_cc > skb_id || PTP_WQE_CTR2IDX(ptpsq->skb_fifo_pc) < skb_id) {
> 
> Can you explain how this checks for ooo?

That means that if the consumer index is pointing to the skb index which 
is after the index of received skb then FIFO was resynced and drained 
some of skbs and received cqe came out of order. The second check is for 
the situation when counters were wrapped around.

> 
>>   >> +		ptpsq->cq_stats->ooo_cqe++;
>>   >> +		return false;
>>   >> +	}
>>   >
>>   >I honestly don't understand how this could happen, can you please
>>   >provide more information about your issue? Did you actually witness ooo
>>   >completions or is it a theoretical issue?
>>   >We know ptp CQEs can be dropped in some rare cases (that's the reason we
>>   >implemented this resync flow), but completions should always arrive
>>   >in-order.
>>
>> I was also surprised to see OOO completions but it's the reality. With a
>> little bit of debug I found this issue:
> 
> Where are these prints added? I assume inside the 'if
> (mlx5e_ptp_ts_cqe_drop())' statement?
> 

Yes, they were added to mlx5e_ptp_ts_cqe_drop() function but effectively 
the same as if added in the if-statement.

>>
>> [65578.231710] FIFO drop found, skb_cc = 141, skb_id = 140
> 
> Is this the first drop? In order for skb_cc to reach 141 it means it has
> already seen skb_id 140 (and consumed it). But here we see skb_id 140
> again? Is it a duplicate completion? Or is it a full wraparound?
> I'm now realising that the naming of the variables is very confusing,
> skb_cc isn't really the consumer counter, it is the cosumer index
> (masked value).
> 

Well, if I remember correctly it wasn't the first drop. That's what I 
was ably to recover from my console's log. But it's better to examine 
next lines of the log.

>> [65578.293358] FIFO drop found, skb_cc = 141, skb_id = 143
> 
> How come we see the same skb_cc twice? When a drop is found we increment it.

First of all I fixed FIFO code not to drain the whole queue once it 
receives ooo cqe. Once it received skb_id lower than skb_cc, it was 
simply dropping cqe because we know than ids in the queue are ascending 
and there is no need to search for lower values. Then skb_id 143 came, 
but skb_cc was not changed and was pointing to 141. The queue was 
resynced to skb_cc 143 at that point. Then skb_id 144 came and it was fine.

>> [65578.301240] FIFO drop found, skb_cc = 145, skb_id = 142

Then apparently skb_id 142 comes. The queue was drained (re-synced) to 
143 before and skb_cc 142 was dropped from the queue during this event.

>> [65578.365277] FIFO drop found, skb_cc = 173, skb_id = 141
>> [65578.426681] FIFO drop found, skb_cc = 173, skb_id = 145
>> [65578.488089] FIFO drop found, skb_cc = 173, skb_id = 146
>> [65578.549489] FIFO drop found, skb_cc = 173, skb_id = 147
>> [65578.610897] FIFO drop found, skb_cc = 173, skb_id = 148
>> [65578.672301] FIFO drop found, skb_cc = 173, skb_id = 149

Not sure what happend then to move skb_cc to 173, but we can see that 
missed cqe are coming now and dropped again

> 
> Confusing :S, did you manage to make sense out of these prints? We need
> prints when !dropped as well, otherwise it's impossible to tell when a
> wraparound occurred.

Printig of !dropped events creates a lot of mess in our setup as we are 
running with this issue on PTP grand master machine.

> 
> Anyway, I'd like to zoom out for a second, the whole fifo was designed
> under the assumption that completions are in-order (this is a guarantee
> for all SQs, not just ptp ones!), this fix seems more of a bandage that
> potentially hides a more severe issue.
> 

I do agree that it looks like a bandage but it's better to have a 
mitigation with possible drops of timestamps instead of kernel crashes 
because of use-after-free and memory corruptions.

>>
>> It really shows that CQE are coming OOO sometimes.
> 
> Can we reproduce it somehow?
> Can you please try to update your firmware version? I'm quite confident
> that this issue is fixed already.
> 

The firmware is pretty new - 22.35.1012 (MT_0000000500), don't believe 
there is a newer GA release to test.
I can reproduce it easily on a couple of machines now.

>>
>>   >> +
>>   >> +	while (skb_cc != skb_id && (skb =
>> mlx5e_skb_fifo_pop(&ptpsq->skb_fifo))) {
>>   >>  		hwts.hwtstamp = mlx5e_skb_cb_get_hwts(skb)->cqe_hwtstamp;
>>   >>  		skb_tstamp_tx(skb, &hwts);
>>   >>  		ptpsq->cq_stats->resync_cqe++;
>>   >>  		skb_cc = PTP_WQE_CTR2IDX(ptpsq->skb_fifo_cc);
>>   >>  	}
>>   >> +
>>   >> +	if (!skb) {
>>   >> +		ptpsq->cq_stats->fifo_empty++;
>>   >
>>   >Hmm, for this to happen you need _all_ ptp CQEs to drop and wraparound
>>   >the SQ?
>>
>> Yep, and that's what I've seen before I fixed mlx5e_ptp_ts_cqe_drop()
>> check. I added this counter just to be sure I won't happen again.
>>
>>   >> +		return false;
>>   >> +	}
>>   >> +
>>   >> +	return true;
>>   >>  }
>>   >>
>>   >>  static void mlx5e_ptp_handle_ts_cqe(struct mlx5e_ptpsq *ptpsq,
>>   >> @@ -109,7 +120,7 @@ static void mlx5e_ptp_handle_ts_cqe(struct
>> mlx5e_ptpsq *ptpsq,
>>   >>  	u16 skb_id = PTP_WQE_CTR2IDX(be16_to_cpu(cqe->wqe_counter));
>>   >>  	u16 skb_cc = PTP_WQE_CTR2IDX(ptpsq->skb_fifo_cc);
>>   >>  	struct mlx5e_txqsq *sq = &ptpsq->txqsq;
>>   >> -	struct sk_buff *skb;
>>   >> +	struct sk_buff *skb = NULL;
>>   >>  	ktime_t hwtstamp;
>>   >>
>>   >>  	if (unlikely(MLX5E_RX_ERR_CQE(cqe))) {
>>   >> @@ -118,8 +129,10 @@ static void mlx5e_ptp_handle_ts_cqe(struct
>> mlx5e_ptpsq *ptpsq,
>>   >>  		goto out;
>>   >>  	}
>>   >>
>>   >> -	if (mlx5e_ptp_ts_cqe_drop(ptpsq, skb_cc, skb_id))
>>   >> -		mlx5e_ptp_skb_fifo_ts_cqe_resync(ptpsq, skb_cc, skb_id);
>>   >> +	if (mlx5e_ptp_ts_cqe_drop(ptpsq, skb_cc, skb_id) &&
>>   >> +	    !mlx5e_ptp_skb_fifo_ts_cqe_resync(ptpsq, skb_cc, skb_id)) {
>>   >> +		goto out;
>>   >> +	}
>>   >>
>>   >>  	skb = mlx5e_skb_fifo_pop(&ptpsq->skb_fifo);
>>   >>  	hwtstamp = mlx5e_cqe_ts_to_ns(sq->ptp_cyc2time, sq->clock,
>> get_cqe_ts(cqe));
>>   >> @@ -128,7 +141,8 @@ static void mlx5e_ptp_handle_ts_cqe(struct
>> mlx5e_ptpsq *ptpsq,
>>   >>  	ptpsq->cq_stats->cqe++;
>>   >>
>>   >>  out:
>>   >> -	napi_consume_skb(skb, budget);
>>   >> +	if (skb)
>>   >> +		napi_consume_skb(skb, budget);
>>   >>  }
>>   >>
>>   >>  static bool mlx5e_ptp_poll_ts_cq(struct mlx5e_cq *cq, int budget)
>>   >> diff --git a/drivers/net/ethernet/mellanox/mlx5/core/en/txrx.h
>> b/drivers/net/ethernet/mellanox/mlx5/core/en/txrx.h
>>   >> index aeed165a2dec..0bd2dd694f04 100644
>>   >> --- a/drivers/net/ethernet/mellanox/mlx5/core/en/txrx.h
>>   >> +++ b/drivers/net/ethernet/mellanox/mlx5/core/en/txrx.h
>>   >> @@ -81,7 +81,7 @@ void mlx5e_free_txqsq_descs(struct mlx5e_txqsq *sq);
>>   >>  static inline bool
>>   >>  mlx5e_skb_fifo_has_room(struct mlx5e_skb_fifo *fifo)
>>   >>  {
>>   >> -	return (*fifo->pc - *fifo->cc) < fifo->mask;
>>   >> +	return (u16)(*fifo->pc - *fifo->cc) < fifo->mask;
>>   >
>>   >What is this cast for?
>>
>> To properly check u16 overflow cases. (*fifo->pc - *fifo->cc) is casted
>> to int if we don't put explicit cast here. And it easily ends up with
>> negative value which we be less than mask until fifo->cc overflows too.
> 
> Ack.
> 
>>
>>   >>  }
>>   >>
>>   >>  static inline bool
>>   >> @@ -291,12 +291,16 @@ void mlx5e_skb_fifo_push(struct mlx5e_skb_fifo
>> *fifo, struct sk_buff *skb)
>>   >>  {
>>   >>  	struct sk_buff **skb_item = mlx5e_skb_fifo_get(fifo, (*fifo->pc)++);
>>   >>
>>   >> +	WARN_ONCE((u16)(*fifo->pc - *fifo->cc) > fifo->mask, "%s
>> overflow", __func__);
>>   >
>>   >The fifo is the same size of the SQ, how can it overflow?
>>   >
>>
>> There is one fifo_push call in mlx5e_txwqe_complete before
>> mlx5e_skb_fifo_has_room() is checked, so it can potentially overflow.
>>
>>   >>  	*skb_item = skb;
>>   >>  }

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ