SSDP crash after receiving IGMP message from Access Point

Basic Infos

Hardware

Hardware: ESP-12E
Core Version: 2.1.0

Description

Recently added a new access point and now SSDP enabled ESP units started to crash.
Also using the sample SSDP sketch crashed at the same event, receiving a IGMP membership query from this new access point.

Settings in IDE

Module: NodeMCU 1.0
Flash Size: 4MB
CPU Frequency: 80Mhz
Flash Mode: dio
Flash Frequency: 40Mhz
Upload Using: OTA
Reset Method: nodemcu

Sketch

Provided SSDP sample sketch

Debug Messages

Exception (0):
epc1=0x40106cf6 epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000000 depc=0x00000000
ctx: sys
sp: 3ffffd80 end: 3fffffb0 offset: 01a0

>>>stack>>>
3fffff20:  4021aca3 005e0001 402107c4 3ffed250
3fffff30:  3fff21a4 00000001 4021ace2 402107dd
3fffff40:  4021aaf1 3fff21cc 3ffed250 3ffebff0
3fffff50:  3ffe0000 3fff21a4 3ffeed00 4021b4a4
3fffff60:  3fff21cc 3fff1b8c 3ffec018 3ffed250
3fffff70:  3fff1b8c 00000014 4021a7ee 3fff21cc
3fffff80:  3fff1b8c 3fffdc80 3fff1bf4 3fff0610
3fffff90:  402261a7 3fff21cc 00000000 402062ff
3fffffa0:  40000f49 3fffdab0 3fffdab0 40000f49
<<<stack<<<


Decoding 12 results
0x40106cf6: __umodsi3 at d:\ivan\projects\arduinoesp\toolchain\dl\gcc-xtensa\build-2\xtensa-lx106-elf\libgcc/../../../libgcc/config/xtensa/lib1funcs.S line 696
0x4021aca3: igmp_tmr at ?? line ?
0x402107c4: ieee80211_deliver_data at ?? line ?
0x4021ace2: igmp_tmr at ?? line ?
0x402107dd: ieee80211_deliver_data at ?? line ?
0x4021aaf1: igmp_input at ?? line ?
0x4021b4a4: ip_input at ?? line ?
0x4021a7ee: ethernet_input at ?? line ?
0x402261a7: ets_snprintf at ?? line ?
0x402062ff: loop_task at C:\Tools\arduino-1.6.8P210\portable\packages\esp8266\hardware\esp8266\2.1.0\cores\esp8266/core_esp8266_main.cpp line 43

Want to back this issue? Post a bounty on it! We accept bounties via Bountysource.

[igrr]

That's super weird, because __umodsi3 function doesn't dereference any pointers, it only operates on values. So how it would fail with a null pointer access, i have no idea.
Did i get this correctly that you need to use some special WiFi router to reproduce this? What is the router brand/model, if I may ask?

Well it's one of those el cheapo Wifi repeaters sold under many brandnames. Just a reference:
http://www.satechi.net/index.php/wireless-multifunction-mini-router-repeater-access-point-client-bridge

I've done a Wireshark scan on IGMP traffic and it seems that this device is the only one sending periodic IGMP V2 Membership Queries.

[mangelajo]

umodsi, couldn't that be because of a division by 0 ?

[liquidfalcon]

It is absolutely a division by zero, the actual line it blows up on is a deliberate ill instruction if umodsi is called with zero. @mangelajo. This issue has been around for a while, and is the same as #1505, #1050, and #1262. I don't believe it's down to any particular router, as I've always been able to reproduce it on multiple ones, given the same traffic as above. It seems to happen with just enabling the mDNS library, keeping SSDP / DNS-SD off doesn't affect it.

[igrr]

Latest git version has a new entry in boards menu: "Core development module", which allows one to use lwIP built from source with debugging symbols enables. Perhaps you could try that one to get a better stack trace and narrow down the issue?
I checked mDNS and SSDP on a few routers i had available, but wasn't able to reproduce this, unfortunately.

[liquidfalcon]

So, after building the lwIP version from source, the errors have changed quite a bit - It's dying on pbuf_free now, which is curious. Relatively the same time-to-die, between 30 seconds and a minute after enabling mDNS. Not entirely sure why it changed.

Decoding 18 results
0x40240104: pbuf_free at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/pbuf.c:723
0x40000f68: ?? ??:0
0x40000f58: ?? ??:0
0x4023ff60: sys_check_timeouts at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/timers.c:384
0x4023ea18: tcp_pcb_purge at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/tcp.c:1423
0x4023ecf0: tcp_slowtmr at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/tcp.c:992
0x4023ee90: tcp_tmr at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/tcp.c:127
0x4023fe30: tcpip_tcp_timer at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/timers.c:87
0x4010598a: wdt_feed at ??:?
0x4023ffd5: sys_check_timeouts at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/timers.c:420
0x4023fe28: tcpip_tcp_timer at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/timers.c:81
0x40232b64: ets_timer_handler_isr at ??:?
0x40232b71: ets_timer_handler_isr at ??:?
0x40232bb6: ets_timer_handler_isr at ??:?
0x402192eb: loop_task at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/core_esp8266_main.cpp:43
0x40000f49: ?? ??:0
0x40000f49: ?? ??:0
0x40000f49: ?? ??:0

[igrr]

What does the exception line look like now?

[liquidfalcon]

Ah, that'd probably be helpful, whoops.

Exception (28):
epc1=0x40240104 epc2=0x00000000 epc3=0x00000000 excvaddr=0x0c477c5a depc=0x00000000

ctx: sys
sp: 3ffffd10 end: 3fffffb0 offset: 01a0

[igrr]

That likely indicates heap corruption (use after free, or double free). Maybe the workaround for tcp_abort I made for xcc-built LWIP breaks something when using gcc-built one.

[igrr]

@liquidfalcon do you have any TCP connections happening in your sketch, or just mDNS?

[liquidfalcon]

I do, yeah - Every second I attempt to send a couple K's of data over SSL, with mDNS running in the background, and DNS-SD requests every 60 seconds. Disabling the SSL routines makes it run for a longer period of time, but, this time when it crashes, it looks like it gives us the real error message from before:

Exception (0):
epc1=0x40106c96 epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000000 depc=0x00000000

ctx: sys 
sp: 3ffffd20 end: 3fffffb0 offset: 01a0


Decoding 13 results
0x40106c96: __modsi3 at /home/igrokhotkov/xtensa/crosstool-NG/.build/src/gcc-4.8.2/libgcc/config/xtensa/lib1funcs.S:759
0x40242fd5: igmp_start_timer at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/ipv4/igmp.c:707
 (inlined by) igmp_delaying_member at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/ipv4/igmp.c:726
0x402431ea: igmp_input at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/ipv4/igmp.c:458
0x401004d8: malloc at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/umm_malloc/umm_malloc.c:1662
0x40107508: pvPortMalloc at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/cores/esp8266/heap.c:13
0x40230000: ets_timer_handler_isr at ??:?
0x40243704: ip_input at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/core/ipv4/ip.c:570
0x4024297d: ethernet_input at /home/danielm/arduino-esp8266/hardware/esp8266com/esp8266/tools/sdk/lwip/src/netif/etharp.c:1379
0x4021bc13: pp_tx_idle_timeout at ??:?
0x4021bb86: pp_tx_idle_timeout at ??:?
0x4022fc27: ets_snprintf at ??:?
0x40000f49: ?? ??:0
0x40000f49: ?? ??:0

Now, this would suggest that something is calling igmp_start_timer with a max_time of 0 or 1, which would explain the crash with modulus, as this line is the last call in that function:

 group->timer = (LWIP_RAND() % (max_time - 1)) + 1;

Would it be worth adding a simple conditional to that statement to not subtract one if it's equal to one? Or check if max_time is actually valid, first?

EDIT: Yes, I think that would work. Adding that makes it keep working well past where it used to crash, when max_time is set to 1.

[igrr]

http://savannah.nongnu.org/patch/?8814

[liquidfalcon]

Aha, someone beat us to it. Cheers @igrr. Also, would you happen to have the commit hash you mentioned earlier for tcp_abort? If I can figure out the other crash, I'd be a happy camper with working mDNS again.