Random lwIP Crashes in _POSIX_Mutex_Lock_support()

[Isaac Gutekunst]

On 10/21/2015 08:24 AM, Sebastian Huber wrote:
>
>
> On 21/10/15 14:13, Isaac Gutekunst wrote:
>> Thanks for the reply.
>>
>> On 10/21/2015 01:50 AM, Sebastian Huber wrote:
>>>
>>>
>>> On 20/10/15 16:02, Isaac Gutekunst wrote:
> [...]
>>>
>>>>
>>>> As far as I can tell this would only occur if the caller of pthread_mutex_lock was in a "bad"
>>>> state. I don't believe it is in an interrupt context, and don't know what other bad states
>>>> could exist.
>>>
>>> We have
>>>
>>> #define _CORE_mutex_Check_dispatch_for_seize(_wait) \
>>>    (!_Thread_Dispatch_is_enabled() \
>>>      && (_wait) \
>>>      && (_System_state_Get() >= SYSTEM_STATE_UP))
>>>
>>> What is the thread dispatch disable level and the system state at this point?
>>>
>>> In case the thread dispatch disable level is not zero, then something is probably broken in the
>>> operating system code which is difficult to find. Could be a general memory corruption problem
>>> too. Which RTEMS version do you use?
>>>
>>
>> The thread dispatch disable level is usually -1 or -2.
>> (0xFFFFFFFE or 0xFFFFFFD).
>
> A negative value is very bad, but easy to detect via manual instrumentation (only an hand full
> of spots touch this variable) or hardware breakpoints/watchpoints. Looks the rest of
> _Per_CPU_Information all right?
>
It looks like it's only the thread_dispatch_disable_level that's broken.

We'll go and grep for all places for all the places it's touched, and look for something.

The problem with watchpoints is they fire exceptionally often, and putting in a conditional 
watchpoint slows the code to a crawl, but that may be worth it.

Here are some printouts of the relevant structs right after a crash:

$4 = {
   cpu_per_cpu = {<No data fields>},
   isr_nest_level = 0,
   thread_dispatch_disable_level = 4294967295,
   executing = 0xc01585c8,
   heir = 0xc0154038,
   dispatch_necessary = true,
   time_of_last_context_switch = {
     sec = 2992,
     frac = 10737447432380511034
   },
   Stats = {<No data fields>}
}



This might be excessive information, but the executing struct looks good too:

p *(cpu_self->executing)
$6 = ((null) ?) {
   Object = {
     Node = {
       next = 0xc0153558,
       previous = 0xc0004568
     },
     id = 184614914,
     name = {
       name_p = 0x0,
       name_u32 = 0
     }
   },
   current_state = 0,
   current_priority = 240,
   real_priority = 240,
   priority_generation = 0,
   priority_restore_hint = false,
   resource_count = 0,
   Wait = {
     Node = {
       Chain = {
         next = 0xc015b764,
         previous = 0xc015b760
       },
       RBTree = {
         Node = {
           rbe_left = 0xc015b764,
           rbe_right = 0xc015b760,
           rbe_parent = 0xc0158644,
           rbe_color = 134262661
         }
       }
     },
     id = 1124139010,
     count = 3222636040,
     return_argument = 0x8032101 <_User_extensions_Fatal_visitor>,
     return_argument_second = {
       mutable_object = 0xc0158644,
       immutable_object = 0xc0158644
     },
     option = 1461858615,
     return_code = 0,
     timeout_code = 116,
     queue = 0x0,
     flags = 1028,
     operations = 0x80966d0 <_Thread_queue_Operations_default>,
     spare_heads = 0xc015b760
   },
   Timer = {
     Node = {
       next = 0xc015304c,
       previous = 0xc014f9ec
     },
     state = WATCHDOG_INACTIVE,
     initial = 78,
     delta_interval = 64,
     start_time = 2991580,
     stop_time = 2991580,
     routine = 0x8031cdd <_Thread_Timeout>,
     id = 0,
     user_data = 0xc01585c8
   },
   is_preemptible = true,
   is_fp = true,
   Scheduler = {
     node = 0xc0158784
   },
   cpu_time_budget = 18,
   budget_algorithm = THREAD_CPU_BUDGET_ALGORITHM_NONE,
   budget_callout = 0x0,
   cpu_time_used = {
     sec = 22,
     frac = 11951614103676580982
   },
   Start = {
     entry_point = 0x808c149 <tcpip_thread>,
     prototype = THREAD_START_POINTER,
     pointer_argument = 0x0,
     numeric_argument = 0,
     is_preemptible = true,
     budget_algorithm = THREAD_CPU_BUDGET_ALGORITHM_NONE,
     budget_callout = 0x0,
     isr_level = 0,
     initial_priority = 240,
     core_allocated_stack = true,
     Initial_stack = {
       size = 4096,
       area = 0xc01690f0
     },
     stack = 0xc01690f0,
     tls_area = 0x0
   },
   Post_switch_actions = {
     Chain = {
       Head = {
         Node = {
           next = 0xc01586b0,
           previous = 0x0
         },
         fill = 0xc01586ac
       },
       Tail = {
         fill = 0xc01586b0,
         Node = {
           next = 0x0,
           previous = 0xc01586ac
         }
       }
     }
   },
   Registers = {
     register_r4 = 3222651512,
     register_r5 = 0,
     register_r6 = 0,
     register_r7 = 3222708080,
     register_r8 = 0,
     register_r9 = 0,
     register_r10 = 0,
     register_r11 = 0,
     register_lr = 0x802f269 <_Thread_Do_dispatch+124>,
     register_sp = 0xc0169f70,
     isr_nest_level = 1,
     register_d8 = 0,
     register_d9 = 0,
     register_d10 = 0,
     register_d11 = 0,
     register_d12 = 0,
     register_d13 = 0,
     register_d14 = 0,
     register_d15 = 0
   },
   libc_reent = 0xc0158890,
   API_Extensions = {0xc0158794, 0xc01587c0},
   task_variables = 0x0,
   Key_Chain = {
     Head = {
       Node = {
         next = 0xc015873c,
         previous = 0x0
       },
       fill = 0xc0158738
     },
     Tail = {
       fill = 0xc015873c,
       Node = {
         next = 0x0,
         previous = 0xc0158738
       }
     }
   },
   Life = {
     Action = {
       Node = {
         next = 0x0,
         previous = 0xc000a998 <rtems_libio_iops+56>
       },
       handler = 0x80312b9 <_Thread_Life_action_handler>
     },
     state = THREAD_LIFE_NORMAL,
     terminator = 0x0
   },
   Capture = {
     flags = 0,
     control = 0x0
   },
   extensions = 0xc0158760
}

> On Cortex-M interrupt disable around operating system calls leads to unpredictable system
> behaviour.
>