osSemaphoreAcquire hangs in LWIP with cellular

[amq]

Description

• Type: Bug
• Possibly related issues: Semaphore release occurs before acquisition for TCP socket over UART #4575, Introduction of RTX/CMSIS 5 has broken semaphone signalling #4584, UARTSerial() and mutexes in interrupts #4537
• Priority: Major

---

Bug

Toolchain:
Tested with GCC_ARM

Toolchain version:
6-2017-q1-update

mbed-cli version:
1.1.1

mbed-os sha:
8828635

Similar behavior also observed with c9e63f1

Expected behavior
Can connect to the internet.

Actual behavior
The initial connection hangs with the following trace:

By pausing I get into the Default_Handler with this trace:

Relevant code:

lwip_stack.c

    if (!netif_is_link_up(&lwip_netif)) {
        if (sys_arch_sem_wait(&lwip_netif_linked, 15000) == SYS_ARCH_TIMEOUT) {
            if (ppp) {
                ppp_lwip_disconnect();
            }
            return NSAPI_ERROR_NO_CONNECTION;
        }
    }

lwip_sys_arch.c

u32_t sys_arch_sem_wait(sys_sem_t *sem, u32_t timeout) {
    u32_t start = us_ticker_read();
    
    if (osSemaphoreAcquire(sem->id, (timeout != 0)?(timeout):(osWaitForever)) != osOK)
        return SYS_ARCH_TIMEOUT;
    
    return (us_ticker_read() - start) / 1000;
}

osSemaphoreAcquire is also called before that, and consistently works:

sys_arch_sem_wait(&lwip_tcpip_inited, 0)

This is the call that fails:

sys_arch_sem_wait(&lwip_netif_linked, 15000)

Sometimes I can get past it by stopping with a breakpoint and continuing manually.

I could always successfully connect using 5.4.3 and 5.4.6 with a manually applied #4119 pretty much at all stages of its development.

I'm using the configuration from https://github.com/ARMmbed/mbed-os-example-cellular

[0xc0170]

cc @hasnainvirk @kjbracey-arm @c1728p9 @geky

[kjbracey]

Feels kind of like an OS bug, rather than anything that could be pinned on the lwip/cellular code. That is a timed wait. So how can it never unstick?

But on the other hand, OS bugs are pretty uncommon, just like compiler bugs.

So what could it be? Corruption of the semaphore while waiting? Failure to initialise it? Someone's broken the ticker clock?

Actually, can you confirm which one it's stopping on? Your initial trace seems to show it was stopping on the lwip_tcpip_inited wait, but then you say it was lwip_netif_linked.

[amq]

@kjbracey-arm sorry, the first screenshot was taken at the wrong moment, I've corrected it now. It consistently fails with lwip_netif_linked and works with lwip_tcpip_inited.

Contents of lwip_netif_linked:

{
	id = 0x20004240 <lwip_netif_linked+20>,
	attr = {
		name = 0x0 <osRegisterForOsEvents>,
		attr_bits = 0,
		cb_mem = 0x20004240 <lwip_netif_linked+20>,
		cb_size = 16
	},
	data = {
		id = 5 '\005',
		state = 1 '\001',
		flags = 0 '\0',
		reserved = 0 '\0',
		name = 0x0 <osRegisterForOsEvents>,
		thread_list = 0x0 <osRegisterForOsEvents>,
		tokens = 0,
		max_tokens = 65535
	}
}

[kjbracey]

Hmm, what's the second trace about? What do you mean "by pausing"? Are we looking at a crash during the wait, rather than it not coming out? Someone tried an sprintf and it died?

Possibly a stack overflow? We know the PPP stack is a bit small, and it can crash if there's a frame checksum error - see pull #4677 which addresses that.

[amq]

When blinky (Ticker) stops, I know that the device hung, then I press pause in Eclipse.

Applying #4677 seems to have helped a bit, I can always get past sys_arch_sem_wait(&lwip_netif_linked, 15000) now if I set a breakpoint there and continue manually, but without it, mbed_lwip_bringup_2 still hangs.

• set a breakpoint and continue on mbed_lwip_bringup_2 - hang
• set a breakpoint and continue on sys_arch_sem_wait(&lwip_netif_linked, 15000) - works
• set a breakpoint on the line after sys_arch_sem_wait(&lwip_netif_linked, 15000) - can't reach

[kjbracey]

That suggests some sort of timing-related issue. Try adding a couple-of-second software delay before the sem_wait, see if that changes anything.

Still not sure how it doesn't just continue after 15 seconds though, regardless of whatever else happens.

[amq]

Tried wait_ms(1), wait_ms(5000) and wait_ms(10000), doesn't help. (I did add #include "mbed_wait_api.h")

It is really strange that setting a breakpoint always works, even if I press continue immediately.

[amq]

Can't replicate it at the moment, but I'm not sure the issue is completely gone. Closing until / if it can get replicated again.