logging: Unaligned memory access in log_free

[jfischer-no]

sample: sample/net/rpl_border_router
board: frdm_k64f + mcr20a

console output:

[00:00:05.589,787] <dbg> net_rpl_br_rpl: (0x200089ec): setup_rpl: New RPL dag fde3:2cda:3eed
***** USAGE FAULT *****
  Unaligned memory access
***** Hardware exception *****
Current thread ID = 0x20008f48
Faulting instruction address = 0x587a
Fatal fault in thread 0x20008f48! Aborting.

gdb:

Breakpoint 1, 0x0000587a in atomic_sub (value=1, target=0x2000d6a6 <log_strdup_pool_buf+138>)           
    at /home/john/src/zephyr-project/include/atomic.h:85                                                
85              return __atomic_fetch_sub(target, value, __ATOMIC_SEQ_CST);                             
(gdb) bt
#0  0x0000587a in atomic_sub (value=1, target=0x2000d6a6 <log_strdup_pool_buf+138>)                     
    at /home/john/src/zephyr-project/include/atomic.h:85                                                
#1  atomic_dec (target=0x2000d6a6 <log_strdup_pool_buf+138>)                                            
    at /home/john/src/zephyr-project/include/atomic.h:123                                               
#2  log_free (str=str@entry=0x2000d6aa <log_strdup_pool_buf+142>)                                       
    at /home/john/src/zephyr-project/subsys/logging/log_core.c:547                                      
#3  0x00005a4e in msg_free (msg=<optimized out>)
    at /home/john/src/zephyr-project/subsys/logging/log_msg.c:52                                        
#4  0x00005a8e in log_msg_put (msg=msg@entry=0x2000ddc0 <log_msg_pool_buf+992>)                         
    at /home/john/src/zephyr-project/subsys/logging/log_msg.c:86                                        
#5  0x000055d4 in msg_process (bypass=<optimized out>, msg=0x2000ddc0 <log_msg_pool_buf+992>)           
    at /home/john/src/zephyr-project/subsys/logging/log_core.c:369                                      
#6  log_process (bypass=bypass@entry=false)
    at /home/john/src/zephyr-project/subsys/logging/log_core.c:383                                      
#7  0x000057de in log_process_thread_func (dummy1=<optimized out>, dummy2=<optimized out>,              
    dummy3=<optimized out>) at /home/john/src/zephyr-project/subsys/logging/log_core.c:559              
#8  0x000034bc in _thread_entry (entry=0x57bd <log_process_thread_func>, p1=<optimized out>,            
    p2=<optimized out>, p3=<optimized out>) at /home/john/src/zephyr-project/lib/thread_entry.c:29      
#9  0xaaaaaaaa in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)                              
(gdb) disass atomic_sub
Dump of assembler code for function log_free:
   0x00005870 <+0>:     push    {r0, r1, r2, lr}
   0x00005872 <+2>:     subs    r0, #4
   0x00005874 <+4>:     str     r0, [sp, #4]
   0x00005876 <+6>:     dmb     ish
=> 0x0000587a <+10>:    ldrex   r3, [r0]
   0x0000587e <+14>:    subs    r2, r3, #1
   0x00005880 <+16>:    strex   r1, r2, [r0]
   0x00005884 <+20>:    cmp     r1, #0
   0x00005886 <+22>:    bne.n   0x587a <log_free+10>
   0x00005888 <+24>:    dmb     ish
   0x0000588c <+28>:    cmp     r3, #1
   0x0000588e <+30>:    bne.n   0x5898 <log_free+40>
   0x00005890 <+32>:    add     r1, sp, #4
   0x00005892 <+34>:    ldr     r0, [pc, #12]   ; (0x58a0 <log_free+48>)                                
   0x00005894 <+36>:    bl      0x23f74 <k_mem_slab_free>                                               
   0x00005898 <+40>:    add     sp, #12
   0x0000589a <+42>:    ldr.w   pc, [sp], #4
   0x0000589e <+46>:    nop
   0x000058a0 <+48>:    ldrh    r0, [r7, #60]   ; 0x3c                                                  
   0x000058a2 <+50>:    movs    r0, #0
End of assembler dump.
(gdb) print /x $r0
$2 = 0x2000d6a6
(gdb) x /32c $r0 
0x2000d6a6 <log_strdup_pool_buf+138>:   1 '\001'        0 '\000'        0 '\000'        0 '\000'        102 'f'  100 'd' 101 'e' 51 '3'
0x2000d6ae <log_strdup_pool_buf+146>:   58 ':'  50 '2'  99 'c'  100 'd' 97 'a'  58 ':'  51 '3'  101 'e'
0x2000d6b6 <log_strdup_pool_buf+154>:   101 'e' 97 'a'  58 ':'  52 '4'  100 'd' 49 '1'  52 '4'  58 ':'
0x2000d6be <log_strdup_pool_buf+162>:   58 ':'  49 '1'  0 '\000'        0 '\000'        0 '\000'        0 '\000' 0 '\000'        0 '\000'

[jfischer-no]

Possible workaround is to set block size to multiple of 4, e.g. CONFIG_LOG_STRDUP_MAX_STRING=48. Default for networking is 46, see subsys/logging/Kconfig

To ensure that each memory block is similarly aligned to this boundary, slab_block_size must also be a multiple of N.

@jukkar FYI

[nordic-krch]

Can you check with #10506? There was a bug in mem_slab initialization which is fixed by this commit.

[jfischer-no]

@nordic-krch while checking this the next one appeared, ***** Stack Check Fail! *****.
https://github.com/zephyrproject-rtos/zephyr/blob/master/subsys/logging/log_core.c#L525
What ist the size of the flag? I guess the char pointer sdupl should be incremented and not the u32_t pointer dupl?

Below, stack sentinel will be overwritten:

Breakpoint 1, log_strdup (str=str@entry=0x20012cdc <_main_stack+876> "fde3:2cda:3eea:4d14::1")
    at /home/john/src/zephyr-project/subsys/logging/log_core.c:512
512     {
(gdb) until 524
log_strdup (str=str@entry=0x20012cdc <_main_stack+876> "fde3:2cda:3eea:4d14::1")
    at /home/john/src/zephyr-project/subsys/logging/log_core.c:524
524             *dupl = 1;
(gdb) print dupl
$1 = (u32_t *) 0x200072f0 <log_strdup_pool_buf+144>
(gdb) x /16xw dupl
0x200072f0 <log_strdup_pool_buf+144>:   0x200072c0      0x33656466      0x6463323a      0x65333a61
0x20007300 <log_strdup_pool_buf+160>:   0x343a6165      0x3a343164      0x0000313a      0x00000000
0x20007310 <log_strdup_pool_buf+176>:   0x00000000      0x00000000      0x00000000      0x00000000
0x20007320 <_k_thread_stack_logging>:   0xf0f0f0f0      0xaaaaaaaa      0xaaaaaaaa      0xaaaaaaaa
(gdb) ni
0x000047b0      524             *dupl = 1;
(gdb) 
0x000047b2      524             *dupl = 1;
(gdb) 
0x000047b4      524             *dupl = 1;
(gdb) 
528             strncpy(sdupl, str, CONFIG_LOG_STRDUP_MAX_STRING - 1);
(gdb) 
0x000047ba      528             strncpy(sdupl, str, CONFIG_LOG_STRDUP_MAX_STRING - 1);
(gdb) 
0x000047bc      528             strncpy(sdupl, str, CONFIG_LOG_STRDUP_MAX_STRING - 1);
(gdb) 
525             dupl++;
(gdb) print dupl
$2 = (u32_t *) 0x200072f0 <log_strdup_pool_buf+144>
(gdb) ni
528             strncpy(sdupl, str, CONFIG_LOG_STRDUP_MAX_STRING - 1);
(gdb) print dupl
$3 = (u32_t *) 0x200072f4 <log_strdup_pool_buf+148>
(gdb) until 530
log_strdup (str=str@entry=0x20012cdc <_main_stack+876> "fde3:2cda:3eea:4d14::1")
    at /home/john/src/zephyr-project/subsys/logging/log_core.c:530
530             sdupl[LOG_STRBUF_STR_SIZE - 2] = '~';
(gdb) x /16xw dupl
0x200072f4 <log_strdup_pool_buf+148>:   0x33656466      0x6463323a      0x65333a61      0x343a6165
0x20007304 <log_strdup_pool_buf+164>:   0x3a343164      0x0000313a      0x00000000      0x00000000
0x20007314 <log_strdup_pool_buf+180>:   0x00000000      0x00000000      0x00000000      **0xf0f0f000**
0x20007324 <_k_thread_stack_logging+4>: 0xaaaaaaaa      0xaaaaaaaa      0xaaaaaaaa      0xaaaaaaaa
(gdb) 

[mike-scott]

@jfischer-phytec-iot can you try adding this setting to whatever prj.conf you're using:
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048

When I enabled a bunch of debugging, I also hit a similar error as you described. Turns out the system workqueue stack was getting hammered and needed to be a bit bigger.

[jfischer-no]

@mike-scott here it is a bug, see above

[nordic-krch]

@jfischer-phytec-iot flag is u32_t. It is later on used by atomic_dec() so must be 32bit.

[jfischer-no]

fixed|resolve by ce4be3a