Too many "out of UDP buffer" msg in log

[made-by-love]

Hello, I used the shadowsocks version of tun2socks, I have issue with UDP traffic, I saw many error log of UDP, what the cause it may be?

2020-01-21 16:08:43.860 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:43.860 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:43.982 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:45.600 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:45.866 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:45.988 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:47.606 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:47.869 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:47.992 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:49.609 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:49.873 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:49.993 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:51.612 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:51.876 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:51.996 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:53.617 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:53.881 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:53.999 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:55.620 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:55.884 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:56.002 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:57.623 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:57.887 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:58.005 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:59.625 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:08:59.889 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:00.009 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:01.629 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:02.014 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:03.636 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:04.017 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:05.642 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:06.020 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:07.645 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:08.022 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:09.647 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:10.026 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:11.649 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:12.029 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer
2020-01-21 16:09:13.653 31308-31308/? D/tun2socks: ERROR(SocksUdpGwClient): out of UDP buffer

[4-FLOSS-Free-Libre-Open-Source-Software]

how large is your mtu set? and how large buffers´? [--udpgw-connection-buffer-size <number>]

looked in wireshark trace of tap interface?

[made-by-love]

MTU is 1500, udpgw-connection-buffer-size is defult.

[made-by-love]

It's on android mobile phone, haven't found a way to trace it

[xDragonZ]

shadowsocks/shadowsocks-android#2414

[ambrop72]

The only reason for "out of UDP buffer" errors should be that the packet buffer is in fact full. This will happen when the UDP socket is blocking packets (i.e. rejecting new ones with EAGAIN/EWOULDBLOCK and not indicating being writable via epoll). If you add some logging to the right parts of the code, it may help understanding what is happening with the buffer.

The reason the first packet is not sent immediately is because the send pipeline needs to first request a packet from BufferWriter (send_if), which is asynchronous. The first_job is queued (BPending_Set()) before the send pipeline is initialized, ensuring that it executes after the send pipeline stuff is done, due to LIFO nature of job processing.

[made-by-love]

The only reason for "out of UDP buffer" errors should be that the packet buffer is in fact full. This will happen when the UDP socket is blocking packets (i.e. rejecting new ones with EAGAIN/EWOULDBLOCK and not indicating being writable via epoll). If you add some logging to the right parts of the code, it may help understanding what is happening with the buffer.

The reason the first packet is not sent immediately is because the send pipeline needs to first request a packet from BufferWriter (send_if), which is asynchronous. The first_job is queued (BPending_Set()) before the send pipeline is initialized, ensuring that it executes after the send pipeline stuff is done, due to LIFO nature of job processing.

So in some case, the first packet will send out after the second packet because of LIFO job processing?

[made-by-love]

I also encountered crashes in BSocksClient.c calling report_error job handler:

static void _DebugError_job_handler (DebugError *o)
{
    ASSERT(0);
}

In which case would this happen?

[ambrop72]

So in some case, the first packet will send out after the second packet because of LIFO job processing?

It should not happen. See device_read_handler_send. PacketPassInterface_Done is called before process_device_udp_packet. Which means that the packet processing will be done before the next time that process_device_udp_packet could be called, again due to LIFO processing.

[ambrop72]

Regarding _DebugError_job_handler, there seems to be a violation of the requirement that BSocksClient is freed when BSOCKSCLIENT_EVENT_ERROR or BSOCKSCLIENT_EVENT_ERROR_CLOSED is reported.

[made-by-love]

Regarding _DebugError_job_handler, there seems to be a violation of the requirement that BSocksClient is freed when BSOCKSCLIENT_EVENT_ERROR or BSOCKSCLIENT_EVENT_ERROR_CLOSED is reported.

In which condition will this happen? For release build, this will cause packets can't be sent out.

[kyze8439690]

I don't know whether it is related to this issue or not. Just ignore me if I am wrong.

On some android devices, when mobile network signal is low, which cause network become unavailable, the udp socket fd sendto() operation will be blocking if the udp fd is not NON_BLOCKING.

We found this issue in a signal-shielded room. Maybe you can reproduce the problem in the elevator?