Assertion "pcb->snd_queuelen >= pbuf_clen(next->p)" failed after TCP handshake (IDFGH-5135)

[Harvie]

Hello, i have written my own netif driver on FreeRTOS+LWIP. Pings work reliably, TCP handshake works reliably, but once i start sending data to the established TCP connection it crashes on this:

assertion "pcb->snd_queuelen >= pbuf_clen(next->p)" failed: file "/opt/Espressif/esp-idf/components/lwip/lwip/src/core/tcp_in.c", line 1112, function: tcp_free_acked_segments

My netif has FreeRTOS task which handles communication and then passes received L2 frames to LWIP like this:

p = pbuf_alloc(PBUF_RAW,rx_len,PBUF_POOL);
pbuf_take(p, rx_buf, rx_len);
if(netif->input(p, netif) != ERR_OK) {
  ESP_LOGE(TAG, "Input failed!");
  pbuf_free(p);
}

Netif task runs with same priority as LWIP task. (Both run at ESP_TASK_TCPIP_PRIO defined in esp_task.h, but that is ESP32 specific) When i was running task with higher priority it was causing deadlocks. Now when i run both task on the same priority it gives me assertion mentioned before... Tried even lower priority. Does not help.

Any idea what might be causing this? I am not sure how should i handle the case with netif having its own task sending data to netif->input() Is there some explicit locking required?

Thanks for your help.

---

Please note that i am discussing this also on the LWIP mailing list and so far it seems that i call the API correctly: https://lists.gnu.org/archive/html/lwip-users/2021-04/msg00023.html

Is it possible that there are some modifications specific to esp-idf that might cause it to behave differently from upstream lwip?

[david-cermak]

@Harvie I think this might be related to your IDF issue https://github.com/espressif/esp-idf/issues/6919 as the esp-lwip is really optimized for calling the lwip API only from the TCPIP task. If a raw api needs to be call from the application, we typically use locks and tcpip callbacks using tcpip_send_msg_wait_sem().

[Harvie]

That might be it. My netif driver runs separate FreeRTOS task to handle receival of the packets and once new packet is received it is passed to tcpip_input(). Am i supposed to lock something before i do so? What modification would you suggest me to do in the code attached in the issue description?

[Harvie]

I would love my netif driver to be usefull both on esp-idf and vanilla LWIP. so idealy i can add some #ifdefs with esp-idf specific locking or something like that...

[Harvie]

we typically use locks and tcpip callbacks using tcpip_send_msg_wait_sem().

On the other hand... It seems that tcpip_input() already handles synchronisation using some "mbox" queue to pass data to tcpip_thread context and therefore prevent such data races...

esp-lwip is really optimized for calling the lwip API only from the TCPIP task.

I think this is true for LWIP in general... not just esp-lwip. Are there any actual changes to the codebase that would require different netif behaviour?

[david-cermak]

I think that you're correct about synchronization and the original lwip behavior. As for the difference between vanilla lwip and the esp-lwip on the netif level, there're some additional indicators on ownership of pbufs. This shouldn't cause any trouble, at least not with locking I think (perhaps with memory?). I still think your issues is somehow related to thread synchronization, as you've reported deadlocks for different priorities (plus this assertion has to do with pbuf chaining, which might happen if data get's refused from the tcpip task).

Checked the code you posted and works for me with no issues. Running this from a separate task (passing data from the wifi interface) and tested with different task priorities. The only trouble could be the ESP_L2_TO_L3_COPY, but this applies only to the esp-wifi, if not used correctly it would eventually exhaust internal buffers. Again, this doesn't look like your issue. Or was it wifi, you have written the netif driver for?

Is it possible to post a small project, which could help to reproduce the issue? Does the assert trigger all the time or just randomly? When you talked about the deadlocks (with lower task priorities), could you check which task is blocked on what? Was it the input task blocked on sys_mbox_trypost() ?

Also there're some related debug options, you can turn on:

#define TCP_QLEN_DEBUG                  LWIP_DBG_ON
#define PBUF_DEBUG                      LWIP_DBG_ON

[Harvie]

OK! It was my fault. Now everything works great. I've figured out what was going on, so i will describe it here. Despite the assertion failing in tcp_in.c, the bug was actualy in the output part of driver. My driver was corrupting output packet pbufs.

For most protocols this was OK, because LWIP actualy free()s the packet immediately and noone knows if something is wrong. But TCP is different. It keeps the packet even after being transmited in pcb->snd_buf and it holds it in there until the receival is ACKed by the other host. So everytime packet arrives in tcp_in, the tcp_free_acked_segments() does check all packets in that buffer to see if they were succesfully transported and therefore can be freed. But i've modified the packets in the meantime, so i've broken this mechanism.

This is what i was doing. I've calculated ethernet frame checksum (FCS CRC32) and used pbuf_cat() to append it to the end of that pbuf before passing it to TX queue, because i didn't wanted the actual communication task to loose time calculating CRC32, since it has critical timing requirements. I didn't knew that someone was gonna be working with these packets further (except for calling pbuf_free() on them)

  low_level_output(struct netif *netif, struct pbuf *p) {

  pbuf_ref(p);
  //p = pbuf_coalesce(p, PBUF_RAW_TX);
  if(p->next != NULL)
    ESP_LOGE(TAG, "Packet pbuf not coalesced before CRC!");
  //4 additional bytes for FCS CRC32
  fcs = pbuf_alloc(PBUF_RAW_TX, FCS_LEN, PBUF_RAM);
  if(!fcs) {
    pbuf_free(p);
    ESP_LOGE(TAG, "No memory for TX FCS!");
    return ERR_MEM;
  }
  //Calculate CRC32
  *((uint32_t *)(fcs->payload)) = ethernet_crc32(p->payload, p->len, 0);
  pbuf_cat(p, fcs);
  xQueueSendToBack(mynetif->tx_queue, &p, 0);

  ... }

I have completely fixed this code by using pbuf_copy() to create my own pbuf which i can modify all i want without causing any troubles to TCP stack. I don't call pbuf_ref() on original packet, because i don't reference original pbuf anymore.

  //Alloc with 4 additional bytes for FCS CRC32
  fcs = pbuf_alloc(PBUF_RAW_TX, p->tot_len+FCS_LEN, PBUF_RAM);
  if(!fcs) {
    ESP_LOGE(TAG, "No memory for TX FCS!");
    return ERR_MEM;
  }
  if(pbuf_copy(fcs, p) != ERR_OK) {
    ESP_LOGE(TAG, "Cannot copy TX!");
    return ERR_MEM;
  }
  if(fcs->next != NULL)
    ESP_LOGE(TAG, "Copied packet pbuf not coalesced before CRC!");
  //Calculate CRC32
  *((uint32_t *)(fcs->payload+fcs->tot_len-FCS_LEN)) =
    ethernet_crc32(fcs->payload, fcs->len-FCS_LEN, 0);
  xQueueSendToBack(mynetif->tx_queue, &fcs, 0); 

I wonder if there is way to append (or prepend) data to the packet pbuf without having to ditch the zero copy API using pbuf_ref(), so i can save some RAM. To implement my original logic correctly.

Anyway... This seems to work quite well for me now. Thank you for checking this with me!

Děkuji