newlib-nano: Printf formatting does not work properly for some numeric types

[miri64]

Possibly other boards are effected, too. Compare the following program

#include <stdio.h>
#include <inttypes.h>

int main(void)
{
    uint64_t test = 0xabcdef0123456789;

    printf("%llx\n", test);
    printf("%lx\n", test);
    printf("%" PRIx64 "\n", test);

    return 0;
}

on iot-lab_M3

2014-10-28 13:15:00,163 - INFO # kernel_init(): This is RIOT! (Version: 2014.05-1144-gd91ec-beutlin-od)
2014-10-28 13:15:00,165 - INFO # kernel_init(): jumping into first task...
2014-10-28 13:15:00,166 - INFO # lx
2014-10-28 13:15:00,166 - INFO # a
2014-10-28 13:15:00,166 - INFO # lx

on native

kernel_init(): This is RIOT! (Version: 2014.05-1145-ga2223-beutlin-od)
kernel_init(): jumping into first task...
abcdef0123456789
23456789
abcdef0123456789

and on msba2

2014-10-28 13:15:00,163 - INFO # kernel_init(): This is RIOT! (Version: 2014.05-1144-gd91ec-beutlin-od)
2014-10-28 13:15:00,165 - INFO # kernel_init(): jumping into first task...
2014-10-28 13:15:00,166 - INFO # abcdef0123456789
2014-10-28 13:15:00,166 - INFO # 23456789
2014-10-28 13:15:00,166 - INFO # abcdef0123456789

[miri64]

For msba2 and iot-lab_M3 I used the same toolchain (ARM Embedded with gcc 4.8.4 20140725), btw.

[Kijewski]

Please try printf("%Lx\n", test); and printf("%" PRIx64 "\n", test);

[miri64]

2014-10-28 13:51:09,132 - INFO # 1
2014-10-28 13:51:09,132 - INFO # lx

respectively

[thomaseichinger]

This is a result of newlib-nano. When omitting

export LINKFLAGS += -specs=nano.specs -lc -lnosys

in boards/iot-lab_M3/Makfile.include results should be correct. For the record, printing floating point numbers doesn't work neither. Could you verify this for me?

[OlegHahm]

I only get the right result when setting -O0

[thomaseichinger]

With arm-none-eabi-gcc (GNU Tools for ARM Embedded Processors) 4.8.4 20140725 (release) [ARM/embedded-4_8-branch revision 213147] and -Os without nano.specs I get

2014-10-28 15:16:00,505 - INFO # abcdef0123456789
2014-10-28 15:16:00,505 - INFO # a
2014-10-28 15:16:00,505 - INFO # abcdef0123456789

The second printf throws a warning

main.c:31:5: warning: format '%lx' expects argument of type 'long unsigned int', but argument 2 has type 'uint64_t' [-Wformat=]
     printf("%lx\n", test);
     ^

[miri64]

Get the same result with the same configuration as @thomaseichinger has. The second printf was just a fall-back case, since %llx wasn't functioning. So everything is fine. Should I close this as a memo for future references?

[OlegHahm]

Hm, there's certainly an issue with some formatters and printf in combination with a certain toolchain, platform, and optimization flags.

[thomaseichinger]

@OlegHahm could you tell us your toolchain version and platform? I'd add a section to iot-lab_M3's wiki page.

[thomaseichinger]

As this issue is related to newlib-nano close this as Memo? @OlegHahm @authmillenon

[OlegHahm]

arm-none-eabi-gcc (GNU Tools for ARM Embedded Processors) 4.8.4 20140526 (release) [ARM/embedded-4_8-branch revision 211358] in default configuration gives:

2014-11-24 19:12:46,271 - INFO # kernel_init(): This is RIOT! (Version: e5a3-tbilisi)
2014-11-24 19:12:46,272 - INFO # kernel_init(): jumping into first task...
2014-11-24 19:12:46,273 - INFO # lx
2014-11-24 19:12:46,273 - INFO # a
2014-11-24 19:12:46,273 - INFO # lx

arm-none-eabi-gcc (GNU Tools for ARM Embedded Processors) 4.8.4 20140526 (release) [ARM/embedded-4_8-branch revision 211358] w/o nano.specs gives:

2014-11-24 19:06:42,607 - INFO # kernel_init(): This is RIOT! (Version: e5a3-tbilisi)
2014-11-24 19:06:42,607 - INFO # kernel_init(): jumping into first task...
2014-11-24 19:06:42,607 - INFO # lx
2014-11-24 19:06:42,608 - INFO # a
2014-11-24 19:06:42,608 - INFO # lx

arm-none-eabi-gcc (Arch Repository) 4.9.2 (also w/o nano.specs) gives:

2014-11-24 19:03:54,716 - INFO # kernel_init(): This is RIOT! (Version: e5a3-tbilisi)
2014-11-24 19:03:54,717 - INFO # kernel_init(): jumping into first task...
2014-11-24 19:03:54,717 - INFO # 2345678900000001
2014-11-24 19:03:54,717 - INFO # a
2014-11-24 19:03:54,718 - INFO # 234567890000000a

[DipSwitch]

This problem is probably caused by the stack alignment. Cortex-M stacks MUST be 8 byte aligned I see in the implementation of thread.c you are only aligning to the processor register size.

[OlegHahm]

This should be fixed since https://github.com/RIOT-OS/RIOT/pull/2976 in https://github.com/RIOT-OS/RIOT/blob/master/cpu/cortexm_common/thread_arch.c

[DipSwitch]

Yeah I just saw it in the thread_arch, I've seen this before when the stack was misaligned, my bad.

[OlegHahm]

No problem.

[PeterKietzmann]

But the described bug in this issue is still present?

[OlegHahm]

Long time I haven't checked.

[PeterKietzmann]

Possible job for @A-Paul ? Or are you already busy with work?

[DipSwitch]

Bug is still present. Checked today, to see if the stack alignment was correct and it was.

[OlegHahm]

Wondering if there is anything we can do about this. Seems more like Newlib-nano issue.

[miri64]

Change format types where this bug occurs?

[kaspar030]

use fmt?

[OlegHahm]

:+1: for fmt

[haukepetersen]

How do we proceed on this? Do we just accept that the nano-specs on cortex-m boards do not support printing 64 bit numbers?

[OlegHahm]

Why not using fmt?

[haukepetersen]

sounds good to me. So the fix is: use fmt for printing (u)int64_t. @authmillenon: does this work for you?

[miri64]

Haven't used fmt yet, but I thought there where considerable concerns using self-written printf() alternatives.

[OlegHahm]

Yes, I would not advice to replace printf with fmt.

[haukepetersen]

that was not the point here. But using it plain and simple for 64-bit ints it IMHO fine. So close this issue as fixed (or wontfix)?

[OlegHahm]

Do we currently have any place in the code where a printf() doesn't show the correct output on iotlab-m3?

[haukepetersen]

Im not aware of any

[cgundogan]

AFAIK, all those printfs that use PRIu8 should be broken (untested).

[cnk@think] ~/riotos/RIOT % gg PRIu8                                                                                                                                     [master]
sys/net/gnrc/application_layer/zep/gnrc_zep.c:    DEBUG("zep: initialized radio parameters: chan: %" PRIu8 ", pan: 0x%04" PRIx16
sys/net/gnrc/application_layer/zep/gnrc_zep.c:            DEBUG("zep: malconfigured version: %" PRIu8 "\n", dev->version);
sys/net/gnrc/netif/hdr/gnrc_netif_hdr_print.c:    printf("rssi: %" PRIu8 "  ", hdr->rssi);
sys/net/gnrc/netif/hdr/gnrc_netif_hdr_print.c:    printf("lqi: %" PRIu8 "\n", hdr->lqi);
sys/net/gnrc/network_layer/icmpv6/echo/gnrc_icmpv6_echo.c:    DEBUG("icmpv6_echo: Building echo message with type=%" PRIu8 "id=%" PRIu16
sys/net/gnrc/network_layer/ipv6/ext/gnrc_ipv6_ext.c:                    DEBUG("ipv6_ext: next header = %" PRIu8 "\n", nh);
sys/net/gnrc/network_layer/ipv6/ext/gnrc_ipv6_ext.c:            DEBUG("ipv6_ext: next header = %" PRIu8 "\n", nh);
sys/net/gnrc/network_layer/ipv6/ext/gnrc_ipv6_ext.c:            DEBUG("ipv6_ext: unknown next header: %" PRIu8 "\n", nh);
sys/net/gnrc/network_layer/ipv6/nc/gnrc_ipv6_nc.c:/* For PRIu8 etc. */
sys/net/gnrc/network_layer/ipv6/nc/gnrc_ipv6_nc.c:        DEBUG("ipv6_nc: Set remaining probes to %" PRIu8 "\n", (uint8_t) GNRC_NDP_MAX_MC_NBR_SOL_NUMOF);
sys/net/gnrc/network_layer/ipv6/netif/gnrc_ipv6_netif.c:        DEBUG("ipv6 netif: couldn't add %s/%" PRIu8 " to interface %" PRIkernel_pid "\n: No space left.",
sys/net/gnrc/network_layer/ipv6/netif/gnrc_ipv6_netif.c:    DEBUG("ipv6 netif: Added %s/%" PRIu8 " to interface %" PRIkernel_pid "\n",
sys/net/gnrc/network_layer/ipv6/netif/gnrc_ipv6_netif.c:        DEBUG("%s by %" PRIu8 " bits (used as source address = %s)\n",
sys/net/gnrc/network_layer/ipv6/netif/gnrc_ipv6_netif.c:        DEBUG("%s by %" PRIu8 " bits\n",
sys/net/gnrc/network_layer/ndp/gnrc_ndp.c:/* For PRIu8 etc. */
sys/net/gnrc/network_layer/ndp/internal/gnrc_ndp_internal.c:            DEBUG("PROBE (probe with %" PRIu8 " unicast NS every %" PRIu32 " us)\n",
sys/net/gnrc/network_layer/ndp/internal/gnrc_ndp_internal.c:        DEBUG(" - PIO for %s/%" PRIu8 "\n", ipv6_addr_to_str(addr_str, &addr->addr,
sys/net/gnrc/network_layer/ndp/internal/gnrc_ndp_internal.c:                  PRIu8 "\n", icmpv6_type);
sys/net/gnrc/network_layer/ndp/internal/gnrc_ndp_internal.c:                  PRIu8 "\n", icmpv6_type);
sys/net/gnrc/network_layer/sixlowpan/ctx/gnrc_sixlowpan_ctx.c:        DEBUG("6lo ctx: found context (%u, %s/%" PRIu8 ") ",
sys/net/gnrc/network_layer/sixlowpan/ctx/gnrc_sixlowpan_ctx.c:        DEBUG("6lo ctx: found context (%u, %s/%" PRIu8 ")\n", id,
sys/net/gnrc/network_layer/sixlowpan/ctx/gnrc_sixlowpan_ctx.c:    DEBUG("6lo ctx: update context (%u, %s/%" PRIu8 "), lifetime: %" PRIu16 " min\n",
sys/net/gnrc/network_layer/sixlowpan/frag/gnrc_sixlowpan_frag.c:          "datagram tag: %" PRIu16 ", offset: %" PRIu8 " (%u bytes), "
sys/net/network_layer/ipv6/hdr/ipv6_hdr_print.c:        printf("illegal version field: %" PRIu8 "\n", ipv6_hdr_get_version(hdr));
sys/net/network_layer/ipv6/hdr/ipv6_hdr_print.c:    printf("length: %" PRIu16 "  next header: %" PRIu8 "  hop limit: %" PRIu8 "\n",
sys/net/network_layer/sixlowpan/sixlowpan_print.c:        printf("offset: 0x%" PRIu8 "\n", hdr->offset);
sys/shell/commands/sc_gnrc_6ctx.c:            printf(" %2" PRIu8 "|%39s/%-3" PRIu8 "|%" PRIx8 "|%5" PRIu16 " min\n", i,
tests/conn_ip/ip.c:    printf("Success: started IP server on protocol %" PRIu8 "\n", protocol);
tests/conn_ip/ip.c:            printf("Success: send %u byte to %s (next header: %" PRIu8 ")\n",
tests/driver_mpu9150/main.c:    printf("Compass sample rate: %"PRIu8" Hz\n", dev.conf.compass_sample_rate);
tests/driver_mpu9150/main.c:    printf("Compass X axis factory adjustment: %"PRIu8"\n", dev.conf.compass_x_adj);
tests/driver_mpu9150/main.c:    printf("Compass Y axis factory adjustment: %"PRIu8"\n", dev.conf.compass_y_adj);
tests/driver_mpu9150/main.c:    printf("Compass Z axis factory adjustment: %"PRIu8"\n", dev.conf.compass_z_adj);

[OlegHahm]

In that case (@authmillenon are you aware of any occurrences?) we could close.

[OlegHahm]

@cgundogan, different issue, I would say (though the cause is similar).

[miri64]

In that case (@authmillenon are you aware of any occurrences?) we could close.

Yes, there are still a few occurrences:

$ git grep -e "PRIu64" -e "%llu"
cpu/atmega_common/avr-libc-extra/inttypes.h:#define PRIu64  "llu"   /**< Format string for unsigned 64-bit number */
sys/cbor/cbor.c:            DESERIALIZE_AND_PRINT(uint64_t, uint64_t, "%" PRIu64)
sys/cbor/cbor.c:                DEBUG("(array, length: %"PRIu64")\n", array_length);
sys/cbor/cbor.c:                DEBUG("(map, length: %"PRIu64")\n", map_length);
sys/od/od.c:            strncpy(format, " %24" PRIu64, sizeof(" %24" PRIu64));
tests/posix_semaphore/main.c:        printf("first: waited only %" PRIu64 " usec => FAILED\n", stop);
tests/posix_semaphore/main.c:    printf("first: waited %" PRIu64 " usec\n", stop);
tests/unittests/tests-div/tests-div.c:        DEBUG("Dividing %"PRIu64" by 15625...\n", u64_test_values[i]);
tests/unittests/tests-div/tests-div.c:        DEBUG("Dividing %"PRIu64" by 1000000...\n", u64_test_values[i]);

[miri64]

od could be ported to fmt completely maybe... But for that we need octal conversion (or we drop support for octal printing there)

[miri64]

fmt doesn't support leading 0s though...

[miri64]

(or any padding for that matter).

[haukepetersen]

@authmillenon and me just agreed offline: postponed

[kaspar030]

any news here?

[kYc0o]

It is not solved by #5094 ?

[OlegHahm]

For me the output still looks like

1469561996.539044;m3-136;lx
1469561996.539257;m3-136;20000cfb
1469561996.539424;m3-136;lx

[kYc0o]

So the issue disappeared? (compared to the output on the beginning of this issue)

[miri64]

No, that's basically still the same. It won't disappear unless we activate printf support for longs and long longs in nano specs.

[kYc0o]

AFAIK to activate that will increase code size it isn't?

[OlegHahm]

Yes, that's why we should not do that.

[kYc0o]

So the issue cannot be solved otherwise?

[miri64]

Replace all occurences with usage of fmt maybe.

[kYc0o]

We can postpone it?

[miri64]

Yes. And let's keep up the discussion ;-)