mbed-trace makes DUT crash in linux tests

[ErkkiMehtala]

Now all our linux tests are failing with newest mbed-client version, DUT crash (HW test did still pass). When downngrading mbed-trace 1.2.0 -> 1.1.3 it works ok. Used versions:

mbed-client-testapp 0.1.0 ┣━ mbed-client 1.12.4 ┃ ┣━ mbed-client-c 2.7.3 yotta_modules/mbed-client-c ┃ ┃ ┗━ nanostack-libservice 3.5.3 yotta_modules/nanostack-libservice ┃ ┣━ mbed-client-linux 3.0.3 yotta_modules/mbed-client-linux ┃ ┗━ mbed-client-mbedtls 3.0.0 yotta_modules/mbed-client-mbedtls ┃ ┗━ mbedtls 2.3.0 yotta_modules/mbedtls ┣━ mbed-client-cli 0.2.0 ┗━ mbed-trace 1.2.0

Used command: python clitest.py -v --tc O5040200F061 --tc_cfg mbedclient_cfg.json --env_cfg env_cfg_cases_using_local_mds.json --valgrind --valgrind_tool memcheck --valgrind_text --valgrind_track_origins

Logs (including valgrind report) 2016-06-09_175026.zip

[TeroJaasko]

Something wrong with the va_args changes, did you test the tr_debug() macros from C++?

valgrind:

==14363== Thread 2:
==14363== Invalid read of size 1
==14363==    at 0x57C2943: vfprintf (vfprintf.c:1661)
==14363==    by 0x57E9498: vsnprintf (vsnprintf.c:119)
==14363==    by 0x46C9BD: mbed_vtracef (mbed_trace.c:411)
==14363==    by 0x46C195: mbed_tracef (mbed_trace.c:288)
==14363==    by 0x43EE7C: M2MObjectInstance::create_dynamic_resource_instance(m2m::String const&, m2m::String const&, M2MResourceInstance::ResourceType, bool, unsigned short) (m2mobjectinstance.cpp:179)
==14363==    by 0x438A13: M2MDevice::M2MDevice() (m2mdevice.cpp:66)
==14363==    by 0x4383F7: M2MDevice::get_instance() (m2mdevice.cpp:32)
==14363==    by 0x43090D: M2MInterfaceFactory::create_device() (m2minterfacefactory.cpp:93)
==14363==    by 0x41EB63: M2MLWClient::create_device_object() (lwm2mtest.cpp:277)
==14363==    by 0x42B5DB: lwm2m_client_device_command(int, char**) (cmd_lwm2m.cpp:545)
==14363==    by 0x42A5BE: lwm2m_client_command(int, char**) (cmd_lwm2m.cpp:374)
==14363==    by 0x4669D0: cmd_run (ns_cmdline.c:755)
==14363==  Address 0x1 is not stack'd, malloc'd or (recently) free'd
==14363==

and same in vgdb:

(gdb) bt
#0  0x00000000057c2943 in _IO_vfprintf_internal (s=s@entry=0x6a41720, format=<optimized out>, 
    format@entry=0x4ef8e0 "M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)", ap=ap@entry=0x6a418f8) at vfprintf.c:1661
#1  0x00000000057e9499 in _IO_vsnprintf (string=0x5e420fe "M2MObjectInstance::create_dynamic_resource_instance(resource_name 0m", maxlen=<optimized out>, 
    format=0x4ef8e0 "M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)", args=0x6a418f8) at vsnprintf.c:119
#2  0x000000000046c9be in mbed_vtracef (dlevel=16 '\020', grp=0x4ef84c "mClt", fmt=0x4ef8e0 "M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)", ap=0x6a418f8)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-trace/source/mbed_trace.c:411
#3  0x000000000046c196 in mbed_tracef (dlevel=16 '\020', grp=0x4ef84c "mClt", fmt=0x4ef8e0 "M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)")
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-trace/source/mbed_trace.c:288
#4  0x000000000043ee7d in M2MObjectInstance::create_dynamic_resource_instance (this=0x5e48df0, resource_name=..., resource_type=..., type=M2MResourceInstance::INTEGER, observable=true, 
    instance_id=0) at /home/tero/work/mbed-github-merging/nanomesh-applications/lwm2m/lwm2m-client/source/m2mobjectinstance.cpp:179
#5  0x0000000000438a14 in M2MDevice::M2MDevice (this=0x5e48b00) at /home/tero/work/mbed-github-merging/nanomesh-applications/lwm2m/lwm2m-client/source/m2mdevice.cpp:66
#6  0x00000000004383f8 in M2MDevice::get_instance () at /home/tero/work/mbed-github-merging/nanomesh-applications/lwm2m/lwm2m-client/source/m2mdevice.cpp:32
#7  0x000000000043090e in M2MInterfaceFactory::create_device () at /home/tero/work/mbed-github-merging/nanomesh-applications/lwm2m/lwm2m-client/source/m2minterfacefactory.cpp:93
#8  0x000000000041eb64 in M2MLWClient::create_device_object (this=0x74f5c0 <lwm2m_client>)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/source/lwm2mtest.cpp:277
#9  0x000000000042b5dc in lwm2m_client_device_command (argc=2, argv=0x6a41cd0)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/source/cmd_lwm2m.cpp:545
#10 0x000000000042a5bf in lwm2m_client_command (argc=2, argv=0x6a41cd0)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/source/cmd_lwm2m.cpp:374
#11 0x00000000004669d1 in cmd_run (string_ptr=0x5e48290 "lwm2m-client device")
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-client-cli/source/ns_cmdline.c:755
#12 0x00000000004652b5 in cmd_next (retcode=0)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-client-cli/source/ns_cmdline.c:360
#13 0x000000000042f295 in cmd_ready_cb (retcode=0) at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/source/cmd_commands.cpp:45
#14 0x00000000004651a7 in cmd_ready (retcode=0)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-client-cli/source/ns_cmdline.c:343
#15 0x0000000000464fe0 in cmd_exe (str=0x75e200 <cmd> "lwm2m-client device")
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-client-cli/source/ns_cmdline.c:318
#16 0x0000000000468ce9 in cmd_execute ()
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-client-cli/source/ns_cmdline.c:1261
#17 0x00000000004679b3 in cmd_char_input (u_data=13)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-client-cli/source/ns_cmdline.c:979
#18 0x000000000042f380 in __thread_poll_function () at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/source/cmd_commands.cpp:64
#19 0x0000000004e3f184 in start_thread (arg=0x6a42700) at pthread_create.c:312
#20 0x000000000587137d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
(gdb) f 2
#2  0x000000000046c9be in mbed_vtracef (dlevel=16 '\020', grp=0x4ef84c "mClt", fmt=0x4ef8e0 "M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)", ap=0x6a418f8)
    at /home/tero/work/mbed-github-merging/nanomesh-applications/mbed-clitest/mbed-client-testapp/yotta_modules/mbed-trace/source/mbed_trace.c:411
411                 retval = vsnprintf(ptr, bLeft, fmt, ap);
(gdb) p ptr
$1 = 0x5e420fe "M2MObjectInstance::create_dynamic_resource_instance(resource_name 0m"
(gdb) p bLeft
$2 = 994
(gdb) p fmt
$3 = 0x4ef8e0 "M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)"
(gdb) p ap
$4 = (struct __va_list_tag *) 0x6a418f8
(gdb) p *(char **)(((char *)ap[0].reg_save_area)+ap[0].gp_offset)
$5 = 0x0
(gdb) p *ap
$7 = {gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x6a419d0, reg_save_area = 0x6a41910}
(gdb) f 4
#4  0x000000000043ee7d in M2MObjectInstance::create_dynamic_resource_instance (this=0x5e48df0, resource_name=..., resource_type=..., type=M2MResourceInstance::INTEGER, observable=true, 
    instance_id=0) at /home/tero/work/mbed-github-merging/nanomesh-applications/lwm2m/lwm2m-client/source/m2mobjectinstance.cpp:179
179     tr_debug("M2MObjectInstance::create_dynamic_resource_instance(resource_name %s)",resource_name.c_str());
(gdb) p resource_name
$8 = (const m2m::String &) @0x6a41ac0: {p = 0x5e49530 "11", allocated_ = 3, size_ = 2, static npos = 18446744073709551615}

[jupe]

@kjbracey-arm has fix already. so fix is coming soon :)