m2gl025_miv-zephyr-v2.2.0-2229-g9b055ecf82.xml

[0/1] cd /home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/sanity-out/m2gl025_miv/tests/posix/common/portability.posix.common && /usr/bin/renode --disable-xwt --port -2 --pid-file renode.pid -e '$bin=@/home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/sanity-out/m2gl025_miv/tests/posix/common/portability.posix.common/zephyr/zephyr.elf; include @/home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/boards/riscv/m2gl025_miv/support/m2gl025_miv.resc; s'
04:45:23.5108 [INFO] Loaded monitor commands from: /opt/renode/./scripts/monitor.py
04:45:23.6088 [INFO] Including script: /home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/boards/riscv/m2gl025_miv/support/m2gl025_miv.resc
04:45:23.6387 [INFO] System bus created.
04:45:24.8234 [DEBUG] Segment size automatically calculated to value 64KiB
04:45:24.8275 [DEBUG] Segment size automatically calculated to value 64KiB
04:45:24.8293 [DEBUG] Segment size automatically calculated to value 64KiB
04:45:24.8310 [DEBUG] Segment size automatically calculated to value 4MiB
04:45:25.1652 [WARNING] Writing to an output GPIO pin #0
04:45:25.1655 [WARNING] Writing to an output GPIO pin #1
04:45:25.1656 [WARNING] Writing to an output GPIO pin #2
04:45:25.7009 [DEBUG] sysbus: Loading ELF /home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/sanity-out/m2gl025_miv/tests/posix/common/portability.posix.common/zephyr/zephyr.elf.
04:45:25.7139 [INFO] sysbus: Loading segment of 70636 bytes length at 0x80000000.
04:45:25.7290 [DEBUG] sysbus: Segment loaded.
04:45:25.7293 [INFO] sysbus: Loading segment of 592 bytes length at 0x800113EC.
04:45:25.7296 [DEBUG] sysbus: Segment loaded.
04:45:25.7299 [INFO] sysbus: Loading segment of 31408 bytes length at 0x80040250.
04:45:25.7300 [DEBUG] sysbus: Segment loaded.
04:45:25.7883 [INFO] cpu: Setting PC value to 0x80000000.
04:45:25.8695 [INFO] Mi-V: Machine started.
04:45:26.0146 [WARNING] plic: Unhandled write to offset 0x200000, value 0x0.
04:45:26.0287 [WARNING] uart: Unhandled write to offset 0xC. Unhandled bits: [0] when writing value 0x1. Tags: BIT8 (0x1).
04:45:26.0879 [DEBUG] uart: [+0.82s host +0.2ms virt 0.2ms virt from start] *** Booting Zephyr OS build zephyr-v2.2.0-2229-g9b055ecf82c3  ***
04:45:26.0955 [DEBUG] uart: [+3.47ms host +0s virt 0.2ms virt from start]   Running test suite posix_apis
04:45:26.0956 [DEBUG] uart: [+0.95ms host +0s virt 0.2ms virt from start]   ===================================================================
04:45:26.0956 [DEBUG] uart: [+1.31ms host +0.1ms virt 0.3ms virt from start]   starting test - test_posix_pthread_execution
04:45:26.1513 [DEBUG] uart: [+57.53ms host +0.1ms virt 0.4ms virt from start]   Thread 0 starting with scheduling policy 0 & priority 15
04:45:26.1607 [DEBUG] uart: [+9.49ms host +0s virt 0.4ms virt from start]   Thread 1 starting with scheduling policy 0 & priority 15
04:45:26.1662 [DEBUG] uart: [+5.54ms host +0.1ms virt 0.5ms virt from start]   Thread 2 starting with scheduling policy 0 & priority 15
04:45:51.7218 [DEBUG] uart: [+25.56s host +0.61s virt 0.62s virt from start]   Bounce test OK
04:45:51.7408 [DEBUG] uart: [+18.94ms host +0.1ms virt 0.62s virt from start]   Barrier test OK
04:45:51.7526 [DEBUG] uart: [+11.77ms host +0s virt 0.62s virt from start]   PASS - test_posix_pthread_execution
04:45:51.7564 [DEBUG] uart: [+3.78ms host +0.1ms virt 0.62s virt from start]   ===================================================================
04:45:51.7603 [DEBUG] uart: [+4.07ms host +0s virt 0.62s virt from start]   starting test - test_posix_pthread_termination
04:45:51.7768 [DEBUG] uart: [+16.53ms host +0.1ms virt 0.62s virt from start]   Thread 0 starting with a priority of 4
04:45:51.7783 [DEBUG] uart: [+1.53ms host +0s virt 0.62s virt from start]   Cancelling thread 0
04:45:51.7830 [DEBUG] uart: [+4.7ms host +0.1ms virt 0.62s virt from start]   Thread 1 starting with a priority of 3
04:45:51.7842 [DEBUG] uart: [+1.22ms host +0s virt 0.62s virt from start]   Cancelling thread 1
04:45:51.7856 [DEBUG] uart: [+1.38ms host +0s virt 0.62s virt from start]   Thread 1 could not be cancelled
04:45:51.7875 [DEBUG] uart: [+1.82ms host +0s virt 0.62s virt from start]   Thread 2 starting with a priority of 2
04:45:51.7889 [DEBUG] uart: [+1.47ms host +0.1ms virt 0.62s virt from start]   Cancelling thread 2
04:45:51.7900 [DEBUG] uart: [+1.05ms host +0s virt 0.62s virt from start]   Thread 3 starting with a priority of 1
04:45:51.7908 [DEBUG] uart: [+0.81ms host +0s virt 0.62s virt from start]   Cancelling thread 3
04:45:51.7930 [DEBUG] uart: [+2.23ms host +0s virt 0.62s virt from start]   Thread 3 could not be cancelled
04:45:51.8186 [DEBUG] uart: [+25.53ms host +10ms virt 0.63s virt from start]   PASS - test_posix_pthread_termination
04:45:51.8237 [DEBUG] uart: [+5.1ms host +0.1ms virt 0.63s virt from start]   ===================================================================
04:45:51.8249 [DEBUG] uart: [+1.22ms host +0s virt 0.63s virt from start]   starting test - test_posix_multiple_threads_single_key
04:45:51.8334 [DEBUG] uart: [+8.44ms host +0s virt 0.63s virt from start]   
04:45:51.8444 [DEBUG] uart: [+11.09ms host +0s virt 0.63s virt from start]   Different threads set different values to same key:
04:45:51.8614 [DEBUG] uart: [+16.99ms host +0.2ms virt 0.63s virt from start]   thread 0: set value = -2147215508 and retrieved value = -2147215508
04:45:51.8781 [DEBUG] uart: [+16.66ms host +0.1ms virt 0.63s virt from start]   thread 1: set value = -2147215268 and retrieved value = -2147215268
04:45:51.8972 [DEBUG] uart: [+18.98ms host +0s virt 0.63s virt from start]   
04:45:51.8996 [DEBUG] uart: [+2.52ms host +0s virt 0.63s virt from start]   PASS - test_posix_multiple_threads_single_key
04:45:51.9012 [DEBUG] uart: [+1.66ms host +0.1ms virt 0.63s virt from start]   ===================================================================
04:45:51.9024 [DEBUG] uart: [+1.16ms host +0s virt 0.63s virt from start]   starting test - test_posix_single_thread_multiple_keys
04:45:51.9050 [DEBUG] uart: [+2.67ms host +0s virt 0.63s virt from start]   
04:45:51.9068 [DEBUG] uart: [+1.73ms host +0.1ms virt 0.63s virt from start]   Single thread associates its value with different keys:
04:45:51.9137 [DEBUG] uart: [+6.92ms host +0.1ms virt 0.63s virt from start]   key 0: set value = -2147215060 and retrieved value = -2147215060
04:45:51.9163 [DEBUG] uart: [+2.63ms host +0s virt 0.63s virt from start]   key 1: set value = -2147215060 and retrieved value = -2147215060
04:45:51.9179 [DEBUG] uart: [+1.54ms host +0.1ms virt 0.63s virt from start]   
04:45:51.9214 [DEBUG] uart: [+3.58ms host +0s virt 0.63s virt from start]   PASS - test_posix_single_thread_multiple_keys
04:45:51.9230 [DEBUG] uart: [+1.61ms host +0.1ms virt 0.63s virt from start]   ===================================================================
04:45:51.9238 [DEBUG] uart: [+0.77ms host +0s virt 0.63s virt from start]   starting test - test_posix_clock
04:45:51.9247 [DEBUG] uart: [+0.86ms host +0s virt 0.63s virt from start]   POSIX clock APIs
04:45:51.9784 [DEBUG] uart: [+53.71ms host +20.2ms virt 0.65s virt from start]   POSIX clock APIs test done
04:45:51.9790 [DEBUG] uart: [+0.6ms host +0s virt 0.65s virt from start]   PASS - test_posix_clock
04:45:51.9801 [DEBUG] uart: [+1.08ms host +0s virt 0.65s virt from start]   ===================================================================
04:45:51.9815 [DEBUG] uart: [+1.39ms host +0.1ms virt 0.65s virt from start]   starting test - test_posix_semaphore
04:45:52.1468 [DEBUG] uart: [+0.17s host +50.1ms virt 0.7s virt from start]   PASS - test_posix_semaphore
04:45:52.1496 [DEBUG] uart: [+2.8ms host +0.1ms virt 0.7s virt from start]   ===================================================================
04:45:52.1503 [DEBUG] uart: [+0.74ms host +0s virt 0.7s virt from start]   starting test - test_posix_normal_mutex
04:45:52.1629 [DEBUG] uart: [+12.57ms host +2.2ms virt 0.7s virt from start]   mutex lock is taken
04:45:52.1643 [DEBUG] uart: [+1.38ms host +0s virt 0.7s virt from start]   PASS - test_posix_normal_mutex
04:45:52.1658 [DEBUG] uart: [+1.47ms host +0.1ms virt 0.7s virt from start]   ===================================================================
04:45:52.1665 [DEBUG] uart: [+0.76ms host +0s virt 0.7s virt from start]   starting test - test_posix_recursive_mutex
04:45:52.1687 [DEBUG] uart: [+2.14ms host +0s virt 0.7s virt from start]   recrusive mutex lock is taken
04:45:52.1826 [DEBUG] uart: [+13.88ms host +0.1ms virt 0.7s virt from start]   PASS - test_posix_recursive_mutex
04:45:52.1837 [DEBUG] uart: [+1.14ms host +0s virt 0.7s virt from start]   ===================================================================
04:45:52.1843 [DEBUG] uart: [+0.61ms host +0s virt 0.7s virt from start]   starting test - test_posix_mqueue
04:45:52.2190 [DEBUG] uart: [+34.62ms host +0.5ms virt 0.7s virt from start]   PASS - test_posix_mqueue
04:45:52.2210 [DEBUG] uart: [+1.73ms host +0s virt 0.7s virt from start]   ===================================================================
04:45:52.2373 [DEBUG] uart: [+16.58ms host +0s virt 0.7s virt from start]   starting test - test_posix_realtime
04:45:52.2382 [DEBUG] uart: [+0.97ms host +0s virt 0.7s virt from start]   POSIX clock set APIs
04:45:52.2392 [DEBUG] uart: [+0.98ms host +0.1ms virt 0.7s virt from start]   
04:45:52.2448 [DEBUG] uart: [+5.31ms host +0s virt 0.7s virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/posix/common/src/clock.c:65: test_posix_realtime: (rts.tv_sec not equal to mts.tv_sec)
04:45:52.2477 [DEBUG] uart: [+3.17ms host +0s virt 0.7s virt from start]   Seconds not equal
04:45:52.2511 [DEBUG] uart: [+3.33ms host +0.1ms virt 0.7s virt from start]   FAIL - test_posix_realtime
04:45:52.2525 [DEBUG] uart: [+1.46ms host +0s virt 0.7s virt from start]   ===================================================================
04:45:52.2533 [DEBUG] uart: [+0.76ms host +0s virt 0.7s virt from start]   starting test - test_posix_timer
04:45:52.2540 [DEBUG] uart: [+0.76ms host +0s virt 0.7s virt from start]   POSIX timer test
04:45:52.2798 [DEBUG] uart: [+25.71ms host +1.2ms virt 0.7s virt from start]   Timer fires every 0 secs and  100000000 nsecs
04:45:52.2810 [DEBUG] uart: [+1.33ms host +0s virt 0.7s virt from start]   Time remaining to fire 0 secs and  880000000 nsecs
04:45:52.3013 [DEBUG] uart: [+20.29ms host +8.8ms virt 0.71s virt from start]   Handler Signal value :20 for 1 times
04:45:52.3067 [DEBUG] uart: [+5.31ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 2 times
04:45:52.3120 [DEBUG] uart: [+5.37ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 3 times
04:45:52.3178 [DEBUG] uart: [+5.8ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 4 times
04:45:52.3263 [DEBUG] uart: [+8ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 5 times
04:45:52.3520 [DEBUG] uart: [+26.1ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 6 times
04:45:52.3835 [DEBUG] uart: [+19.14ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 7 times
04:45:52.3873 [DEBUG] uart: [+16.22ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 8 times
04:45:52.3904 [DEBUG] uart: [+3.16ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 9 times
04:45:52.3978 [DEBUG] uart: [+7.44ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 10 times
04:45:52.4021 [DEBUG] uart: [+4.24ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 11 times
04:45:52.4055 [DEBUG] uart: [+3.44ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 12 times
04:45:52.4133 [DEBUG] uart: [+7.79ms host +0.3ms virt 0.72s virt from start]   PASS - test_posix_timer
04:45:52.4145 [DEBUG] uart: [+1.16ms host +0s virt 0.72s virt from start]   ===================================================================
04:45:52.4239 [DEBUG] uart: [+9.45ms host +0.1ms virt 0.72s virt from start]   starting test - test_posix_rw_lock
04:45:52.4265 [DEBUG] uart: [+2.59ms host +0s virt 0.72s virt from start]   
04:45:52.4274 [DEBUG] uart: [+0.89ms host +0s virt 0.72s virt from start]   main acquire WR lock and 3 threads acquire RD lock
04:45:52.4450 [DEBUG] uart: [+14.12ms host +0.1ms virt 0.72s virt from start]   Thread 2 scheduling policy = 1 & priority 3 started
04:45:52.4451 [DEBUG] uart: [+2.01ms host +0s virt 0.72s virt from start]   Not able to get RD lock on trying, try again
04:45:52.4466 [DEBUG] uart: [+3.03ms host +0.1ms virt 0.72s virt from start]   Thread 1 scheduling policy = 1 & priority 2 started
04:45:52.4476 [DEBUG] uart: [+1.02ms host +0s virt 0.72s virt from start]   Not able to get RD lock on trying, try again
04:45:52.4487 [DEBUG] uart: [+1.06ms host +0s virt 0.72s virt from start]   Thread 0 scheduling policy = 1 & priority 1 started
04:45:52.4660 [DEBUG] uart: [+17.3ms host +0.1ms virt 0.72s virt from start]   Not able to get RD lock Parent thread releasing WR lock
04:45:52.4677 [DEBUG] uart: [+1.76ms host +0s virt 0.72s virt from start]   Thread 2 got RD lock
04:45:52.4684 [DEBUG] uart: [+0.7ms host +0s virt 0.72s virt from start]   Thread 1 got RD lock
04:45:52.4697 [DEBUG] uart: [+1.26ms host +0.1ms virt 0.72s virt from start]   on trying, try again
04:45:52.4702 [DEBUG] uart: [+0.51ms host +0s virt 0.72s virt from start]   Thread 0 got RD lock
04:45:52.4718 [DEBUG] uart: [+1.56ms host +0.1ms virt 0.72s virt from start]   Parent thread acquiring WR lock again
04:45:52.4731 [DEBUG] uart: [+1.33ms host +0s virt 0.72s virt from start]   Thread 2 releasing RD lock
04:45:52.4740 [DEBUG] uart: [+0.9ms host +0s virt 0.72s virt from start]   Thread 2 acquiring WR lock
04:45:52.4756 [DEBUG] uart: [+1.61ms host +0.1ms virt 0.72s virt from start]   Thread 1 releasing RD lock
04:45:52.4763 [DEBUG] uart: [+0.65ms host +0s virt 0.72s virt from start]   Thread 1 acquiring WR lock
04:45:52.4771 [DEBUG] uart: [+0.89ms host +0s virt 0.72s virt from start]   Thread 0 releasing RD lock
04:45:52.4829 [DEBUG] uart: [+5.76ms host +0.1ms virt 0.72s virt from start]   Parent thread acquired WR lock again
04:45:52.4838 [DEBUG] uart: [+0.94ms host +0s virt 0.72s virt from start]   Thread 0 acquiring WR lock
04:45:52.4873 [DEBUG] uart: [+3.5ms host +0.2ms virt 0.72s virt from start]   Parent thread releasing WR lock again
04:45:52.4878 [DEBUG] uart: [+0.48ms host +0s virt 0.72s virt from start]   
04:45:52.4884 [DEBUG] uart: [+0.56ms host +0s virt 0.72s virt from start]   3 threads acquire WR lock
04:45:52.4894 [DEBUG] uart: [+1.08ms host +0s virt 0.72s virt from start]   Main thread acquiring RD lock
04:45:52.4928 [DEBUG] uart: [+3.38ms host +0.1ms virt 0.72s virt from start]   Thread 2 acquired WR lock
04:45:52.4976 [DEBUG] uart: [+4.72ms host +0.2ms virt 0.72s virt from start]   Thread 2 releasing WR lock
04:45:52.5001 [DEBUG] uart: [+2.53ms host +0s virt 0.72s virt from start]   Main thread acquired RD lock
04:45:52.5051 [DEBUG] uart: [+5.07ms host +0.2ms virt 0.72s virt from start]   Main thread releasing RD lock
04:45:52.5093 [DEBUG] uart: [+4.2ms host +0s virt 0.72s virt from start]   Thread 1 acquired WR lock
04:45:52.5126 [DEBUG] uart: [+3.16ms host +0.2ms virt 0.72s virt from start]   Thread 1 releasing WR lock
04:45:52.5302 [DEBUG] uart: [+17.66ms host +0s virt 0.72s virt from start]   Thread 0 acquired WR lock
04:45:52.5323 [DEBUG] uart: [+2.15ms host +0.2ms virt 0.72s virt from start]   Thread 0 releasing WR lock
04:45:52.5340 [DEBUG] uart: [+1.67ms host +0s virt 0.72s virt from start]   PASS - test_posix_rw_lock
04:45:52.5358 [DEBUG] uart: [+1.81ms host +0.1ms virt 0.72s virt from start]   ===================================================================
04:45:52.5371 [DEBUG] uart: [+1.3ms host +0s virt 0.72s virt from start]   Test suite posix_apis failed.
04:45:52.5399 [DEBUG] uart: [+2.77ms host +0s virt 0.72s virt from start]   ===================================================================
04:45:52.5415 [DEBUG] uart: [+1.5ms host +0s virt 0.72s virt from start]   PROJECT EXECUTION FAILED

portability.posix.common.posix_timer
portability.posix.common
Time Taken: 32.684682s

portability.posix.common.posix_rw_lock
portability.posix.common
Time Taken: 32.684682s

Test Class: portability.posix.common.newlib

portability.posix.common.newlib.posix_pthread_execution
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_pthread_termination
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_multiple_threads_single_key
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_single_thread_multiple_keys
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_clock
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_semaphore
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_normal_mutex
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_recursive_mutex
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_mqueue
portability.posix.common.newlib
Time Taken: 32.77593s

portability.posix.common.newlib.posix_realtime
portability.posix.common.newlib
Time Taken: 32.77593s

Failed: failed

[0/1] cd /home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/sanity-out/m2gl025_miv/tests/posix/common/portability.posix.common.newlib && /usr/bin/renode --disable-xwt --port -2 --pid-file renode.pid -e '$bin=@/home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/sanity-out/m2gl025_miv/tests/posix/common/portability.posix.common.newlib/zephyr/zephyr.elf; include @/home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/boards/riscv/m2gl025_miv/support/m2gl025_miv.resc; s'
04:45:23.5003 [INFO] Loaded monitor commands from: /opt/renode/./scripts/monitor.py
04:45:23.6383 [INFO] Including script: /home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/boards/riscv/m2gl025_miv/support/m2gl025_miv.resc
04:45:23.6628 [INFO] System bus created.
04:45:24.8253 [DEBUG] Segment size automatically calculated to value 64KiB
04:45:24.8263 [DEBUG] Segment size automatically calculated to value 64KiB
04:45:24.8268 [DEBUG] Segment size automatically calculated to value 64KiB
04:45:24.8272 [DEBUG] Segment size automatically calculated to value 4MiB
04:45:25.1562 [WARNING] Writing to an output GPIO pin #0
04:45:25.1568 [WARNING] Writing to an output GPIO pin #1
04:45:25.1571 [WARNING] Writing to an output GPIO pin #2
04:45:25.6579 [DEBUG] sysbus: Loading ELF /home/buildslave/src/github.com/zephyrproject-rtos/test_results/zephyr/sanity-out/m2gl025_miv/tests/posix/common/portability.posix.common.newlib/zephyr/zephyr.elf.
04:45:25.6718 [INFO] sysbus: Loading segment of 71124 bytes length at 0x80000000.
04:45:25.6875 [DEBUG] sysbus: Segment loaded.
04:45:25.6879 [INFO] sysbus: Loading segment of 608 bytes length at 0x800115D4.
04:45:25.6881 [DEBUG] sysbus: Segment loaded.
04:45:25.6883 [INFO] sysbus: Loading segment of 31408 bytes length at 0x80040260.
04:45:25.6888 [DEBUG] sysbus: Segment loaded.
04:45:25.7495 [INFO] cpu: Setting PC value to 0x80000000.
04:45:25.8357 [INFO] Mi-V: Machine started.
04:45:25.9998 [WARNING] plic: Unhandled write to offset 0x200000, value 0x0.
04:45:26.0275 [WARNING] uart: Unhandled write to offset 0xC. Unhandled bits: [0] when writing value 0x1. Tags: BIT8 (0x1).
04:45:26.1239 [DEBUG] uart: [+0.88s host +0.1ms virt 0.1ms virt from start] *** Booting Zephyr OS build zephyr-v2.2.0-2229-g9b055ecf82c3  ***
04:45:26.1356 [DEBUG] uart: [+14.31ms host +0s virt 0.1ms virt from start]   Running test suite posix_apis
04:45:26.1367 [DEBUG] uart: [+1.1ms host +0s virt 0.1ms virt from start]   ===================================================================
04:45:26.1437 [DEBUG] uart: [+6.94ms host +0.1ms virt 0.2ms virt from start]   starting test - test_posix_pthread_execution
04:45:26.1658 [DEBUG] uart: [+22.15ms host +0.1ms virt 0.3ms virt from start]   Thread 0 starting with scheduling policy 0 & priority 15
04:45:26.1710 [DEBUG] uart: [+5.2ms host +0s virt 0.3ms virt from start]   Thread 1 starting with scheduling policy 0 & priority 15
04:45:26.1730 [DEBUG] uart: [+1.99ms host +0.1ms virt 0.4ms virt from start]   Thread 2 starting with scheduling policy 0 & priority 15
04:45:51.8692 [DEBUG] uart: [+25.7s host +0.61s virt 0.62s virt from start]   Bounce test OK
04:45:51.9034 [DEBUG] uart: [+34.97ms host +0.1ms virt 0.62s virt from start]   Barrier test OK
04:45:51.9261 [DEBUG] uart: [+4.82ms host +0s virt 0.62s virt from start]   PASS - test_posix_pthread_execution
04:45:51.9308 [DEBUG] uart: [+19.36ms host +0.1ms virt 0.62s virt from start]   ===================================================================
04:45:51.9309 [DEBUG] uart: [+0.92ms host +0s virt 0.62s virt from start]   starting test - test_posix_pthread_termination
04:45:51.9344 [DEBUG] uart: [+5.91ms host +0.1ms virt 0.62s virt from start]   Thread 0 starting with a priority of 4
04:45:51.9350 [DEBUG] uart: [+0.59ms host +0s virt 0.62s virt from start]   Cancelling thread 0
04:45:51.9380 [DEBUG] uart: [+3.03ms host +0.1ms virt 0.62s virt from start]   Thread 1 starting with a priority of 3
04:45:51.9387 [DEBUG] uart: [+0.65ms host +0s virt 0.62s virt from start]   Cancelling thread 1
04:45:51.9395 [DEBUG] uart: [+0.75ms host +0s virt 0.62s virt from start]   Thread 1 could not be cancelled
04:45:51.9409 [DEBUG] uart: [+1.44ms host +0s virt 0.62s virt from start]   Thread 2 starting with a priority of 2
04:45:51.9580 [DEBUG] uart: [+17.03ms host +0.1ms virt 0.62s virt from start]   Cancelling thread 2
04:45:51.9589 [DEBUG] uart: [+0.96ms host +0s virt 0.62s virt from start]   Thread 3 starting with a priority of 1
04:45:51.9607 [DEBUG] uart: [+0.64ms host +0s virt 0.62s virt from start]   Cancelling thread 3
04:45:51.9607 [DEBUG] uart: [+0.58ms host +0s virt 0.62s virt from start]   Thread 3 could not be cancelled
04:45:51.9884 [DEBUG] uart: [+28.29ms host +10ms virt 0.63s virt from start]   PASS - test_posix_pthread_termination
04:45:51.9907 [DEBUG] uart: [+2.29ms host +0.1ms virt 0.63s virt from start]   ===================================================================
04:45:51.9918 [DEBUG] uart: [+1.1ms host +0s virt 0.63s virt from start]   starting test - test_posix_multiple_threads_single_key
04:45:52.0048 [DEBUG] uart: [+12.98ms host +0s virt 0.63s virt from start]   
04:45:52.0060 [DEBUG] uart: [+1.23ms host +0s virt 0.63s virt from start]   Different threads set different values to same key:
04:45:52.0171 [DEBUG] uart: [+11.06ms host +0.2ms virt 0.63s virt from start]   thread 0: set value = -2147215492 and retrieved value = -2147215492
04:45:52.0212 [DEBUG] uart: [+4.15ms host +0.1ms virt 0.63s virt from start]   thread 1: set value = -2147215252 and retrieved value = -2147215252
04:45:52.0292 [DEBUG] uart: [+7.96ms host +0s virt 0.63s virt from start]   
04:45:52.0310 [DEBUG] uart: [+1.77ms host +0s virt 0.63s virt from start]   PASS - test_posix_multiple_threads_single_key
04:45:52.0344 [DEBUG] uart: [+3.42ms host +0.1ms virt 0.63s virt from start]   ===================================================================
04:45:52.0356 [DEBUG] uart: [+1.23ms host +0s virt 0.63s virt from start]   starting test - test_posix_single_thread_multiple_keys
04:45:52.0375 [DEBUG] uart: [+1.97ms host +0s virt 0.63s virt from start]   
04:45:52.0394 [DEBUG] uart: [+1.8ms host +0.1ms virt 0.63s virt from start]   Single thread associates its value with different keys:
04:45:52.0455 [DEBUG] uart: [+6.08ms host +0.1ms virt 0.63s virt from start]   key 0: set value = -2147215044 and retrieved value = -2147215044
04:45:52.0473 [DEBUG] uart: [+1.87ms host +0s virt 0.63s virt from start]   key 1: set value = -2147215044 and retrieved value = -2147215044
04:45:52.0525 [DEBUG] uart: [+5.18ms host +0.1ms virt 0.63s virt from start]   
04:45:52.0539 [DEBUG] uart: [+1.39ms host +0s virt 0.63s virt from start]   PASS - test_posix_single_thread_multiple_keys
04:45:52.0562 [DEBUG] uart: [+1.73ms host +0.1ms virt 0.63s virt from start]   ===================================================================
04:45:52.0579 [DEBUG] uart: [+2.29ms host +0s virt 0.63s virt from start]   starting test - test_posix_clock
04:45:52.0588 [DEBUG] uart: [+0.94ms host +0s virt 0.63s virt from start]   POSIX clock APIs
04:45:52.1186 [DEBUG] uart: [+59.69ms host +20.2ms virt 0.65s virt from start]   POSIX clock APIs test done
04:45:52.1193 [DEBUG] uart: [+0.78ms host +0s virt 0.65s virt from start]   PASS - test_posix_clock
04:45:52.1204 [DEBUG] uart: [+1.1ms host +0s virt 0.65s virt from start]   ===================================================================
04:45:52.1213 [DEBUG] uart: [+0.84ms host +0.1ms virt 0.65s virt from start]   starting test - test_posix_semaphore
04:45:52.2557 [DEBUG] uart: [+0.13s host +50.1ms virt 0.7s virt from start]   PASS - test_posix_semaphore
04:45:52.2573 [DEBUG] uart: [+1.58ms host +0.1ms virt 0.7s virt from start]   ===================================================================
04:45:52.2583 [DEBUG] uart: [+1ms host +0s virt 0.7s virt from start]   starting test - test_posix_normal_mutex
04:45:52.2903 [DEBUG] uart: [+31.72ms host +2.2ms virt 0.7s virt from start]   mutex lock is taken
04:45:52.2958 [DEBUG] uart: [+5.69ms host +0s virt 0.7s virt from start]   PASS - test_posix_normal_mutex
04:45:52.3039 [DEBUG] uart: [+8.21ms host +0.1ms virt 0.7s virt from start]   ===================================================================
04:45:52.3047 [DEBUG] uart: [+0.78ms host +0s virt 0.7s virt from start]   starting test - test_posix_recursive_mutex
04:45:52.3071 [DEBUG] uart: [+2.41ms host +0s virt 0.7s virt from start]   recrusive mutex lock is taken
04:45:52.3124 [DEBUG] uart: [+5.22ms host +0.1ms virt 0.7s virt from start]   PASS - test_posix_recursive_mutex
04:45:52.3135 [DEBUG] uart: [+1.16ms host +0s virt 0.7s virt from start]   ===================================================================
04:45:52.3141 [DEBUG] uart: [+0.6ms host +0s virt 0.7s virt from start]   starting test - test_posix_mqueue
04:45:52.3563 [DEBUG] uart: [+42.24ms host +0.5ms virt 0.7s virt from start]   PASS - test_posix_mqueue
04:45:52.3574 [DEBUG] uart: [+1.12ms host +0s virt 0.7s virt from start]   ===================================================================
04:45:52.3581 [DEBUG] uart: [+0.63ms host +0s virt 0.7s virt from start]   starting test - test_posix_realtime
04:45:52.3587 [DEBUG] uart: [+0.61ms host +0s virt 0.7s virt from start]   POSIX clock set APIs
04:45:52.3719 [DEBUG] uart: [+13.26ms host +0.1ms virt 0.7s virt from start]   
04:45:52.3742 [DEBUG] uart: [+2.23ms host +0s virt 0.7s virt from start]       Assertion failed at WEST_TOPDIR/zephyr/tests/posix/common/src/clock.c:65: test_posix_realtime: (rts.tv_sec not equal to mts.tv_sec)
04:45:52.3747 [DEBUG] uart: [+0.55ms host +0s virt 0.7s virt from start]   Seconds not equal
04:45:52.3760 [DEBUG] uart: [+1.28ms host +0.1ms virt 0.7s virt from start]   FAIL - test_posix_realtime
04:45:52.3786 [DEBUG] uart: [+2.64ms host +0s virt 0.7s virt from start]   ===================================================================
04:45:52.3792 [DEBUG] uart: [+0.59ms host +0s virt 0.7s virt from start]   starting test - test_posix_timer
04:45:52.3798 [DEBUG] uart: [+0.57ms host +0s virt 0.7s virt from start]   POSIX timer test
04:45:52.4079 [DEBUG] uart: [+25.9ms host +1.2ms virt 0.7s virt from start]   Timer fires every 0 secs and  100000000 nsecs
04:45:52.4080 [DEBUG] uart: [+1.64ms host +0s virt 0.7s virt from start]   Time remaining to fire 0 secs and  880000000 nsecs
04:45:52.4244 [DEBUG] uart: [+16.7ms host +8.8ms virt 0.71s virt from start]   Handler Signal value :20 for 1 times
04:45:52.4277 [DEBUG] uart: [+3.41ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 2 times
04:45:52.4328 [DEBUG] uart: [+5.12ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 3 times
04:45:52.4358 [DEBUG] uart: [+3.04ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 4 times
04:45:52.4389 [DEBUG] uart: [+3.08ms host +1ms virt 0.71s virt from start]   Handler Signal value :20 for 5 times
04:45:52.4425 [DEBUG] uart: [+3.68ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 6 times
04:45:52.4460 [DEBUG] uart: [+3.41ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 7 times
04:45:52.4488 [DEBUG] uart: [+2.97ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 8 times
04:45:52.4520 [DEBUG] uart: [+3.26ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 9 times
04:45:52.4588 [DEBUG] uart: [+6.76ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 10 times
04:45:52.4640 [DEBUG] uart: [+5.19ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 11 times
04:45:52.4707 [DEBUG] uart: [+6.75ms host +1ms virt 0.72s virt from start]   Handler Signal value :20 for 12 times
04:45:52.4938 [DEBUG] uart: [+21.4ms host +0.3ms virt 0.72s virt from start]   PASS - test_posix_timer
04:45:52.4939 [DEBUG] uart: [+1.1ms host +0s virt 0.72s virt from start]   ===================================================================
04:45:52.4943 [DEBUG] uart: [+1.1ms host +0.1ms virt 0.72s virt from start]   starting test - test_posix_rw_lock
04:45:52.5101 [DEBUG] uart: [+15.78ms host +0s virt 0.72s virt from start]   
04:45:52.5111 [DEBUG] uart: [+1.01ms host +0s virt 0.72s virt from start]   main acquire WR lock and 3 threads acquire RD lock
04:45:52.5172 [DEBUG] uart: [+4.11ms host +0.1ms virt 0.72s virt from start]   Thread 2 scheduling policy = 1 & priority 3 started
04:45:52.5173 [DEBUG] uart: [+1.2ms host +0s virt 0.72s virt from start]   Not able to get RD lock on trying, try again
04:45:52.5184 [DEBUG] uart: [+1.96ms host +0.1ms virt 0.72s virt from start]   Thread 1 scheduling policy = 1 & priority 2 started
04:45:52.5192 [DEBUG] uart: [+0.79ms host +0s virt 0.72s virt from start]   Not able to get RD lock on trying, try again
04:45:52.5205 [DEBUG] uart: [+1.33ms host +0s virt 0.72s virt from start]   Thread 0 scheduling policy = 1 & priority 1 started
04:45:52.5288 [DEBUG] uart: [+6ms host +0.1ms virt 0.72s virt from start]   Not able to get RD lock oParent thread releasing WR lock
04:45:52.5288 [DEBUG] uart: [+1.58ms host +0s virt 0.72s virt from start]   Thread 2 got RD lock
04:45:52.5289 [DEBUG] uart: [+0.65ms host +0s virt 0.72s virt from start]   Thread 1 got RD lock
04:45:52.5302 [DEBUG] uart: [+1.48ms host +0.1ms virt 0.72s virt from start]   n trying, try again
04:45:52.5310 [DEBUG] uart: [+0.78ms host +0s virt 0.72s virt from start]   Thread 0 got RD lock
04:45:52.5358 [DEBUG] uart: [+4.81ms host +0.1ms virt 0.72s virt from start]   Parent thread acquiring WR lock again
04:45:52.5385 [DEBUG] uart: [+2.71ms host +0s virt 0.72s virt from start]   Thread 2 releasing RD lock
04:45:52.5403 [DEBUG] uart: [+1.83ms host +0s virt 0.72s virt from start]   Thread 2 acquiring WR lock
04:45:52.5433 [DEBUG] uart: [+2.93ms host +0.1ms virt 0.72s virt from start]   Thread 1 releasing RD lock
04:45:52.5441 [DEBUG] uart: [+0.8ms host +0s virt 0.72s virt from start]   Thread 1 acquiring WR lock
04:45:52.5450 [DEBUG] uart: [+0.89ms host +0s virt 0.72s virt from start]   Thread 0 releasing RD lock
04:45:52.5464 [DEBUG] uart: [+1.45ms host +0.1ms virt 0.72s virt from start]   Parent thread acquired WR lock again
04:45:52.5475 [DEBUG] uart: [+1.07ms host +0s virt 0.72s virt from start]   Thread 0 acquiring WR lock
04:45:52.5503 [DEBUG] uart: [+2.8ms host +0.2ms virt 0.72s virt from start]   Parent thread releasing WR lock again
04:45:52.5508 [DEBUG] uart: [+0.58ms host +0s virt 0.72s virt from start]   
04:45:52.5517 [DEBUG] uart: [+0.82ms host +0s virt 0.72s virt from start]   3 threads acquire WR lock
04:45:52.5527 [DEBUG] uart: [+1.02ms host +0s virt 0.72s virt from start]   Main thread acquiring RD lock
04:45:52.5581 [DEBUG] uart: [+5.39ms host +0.1ms virt 0.72s virt from start]   Thread 2 acquired WR lock
04:45:52.5663 [DEBUG] uart: [+8.17ms host +0.2ms virt 0.72s virt from start]   Thread 2 releasing WR lock
04:45:52.5680 [DEBUG] uart: [+1.77ms host +0s virt 0.72s virt from start]   Main thread acquired RD lock
04:45:52.5829 [DEBUG] uart: [+14.48ms host +0.2ms virt 0.72s virt from start]   Main thread releasing RD lock
04:45:52.5869 [DEBUG] uart: [+4.11ms host +0s virt 0.72s virt from start]   Thread 1 acquired WR lock
04:45:52.6031 [DEBUG] uart: [+16.37ms host +0.2ms virt 0.72s virt from start]   Thread 1 releasing WR lock
04:45:52.6056 [DEBUG] uart: [+2.6ms host +0s virt 0.72s virt from start]   Thread 0 acquired WR lock
04:45:52.6109 [DEBUG] uart: [+5.2ms host +0.2ms virt 0.72s virt from start]   Thread 0 releasing WR lock
04:45:52.6171 [DEBUG] uart: [+6.27ms host +0s virt 0.72s virt from start]   PASS - test_posix_rw_lock
04:45:52.6193 [DEBUG] uart: [+2.22ms host +0.1ms virt 0.72s virt from start]   ===================================================================
04:45:52.6209 [DEBUG] uart: [+1.66ms host +0s virt 0.72s virt from start]   Test suite posix_apis failed.
04:45:52.6241 [DEBUG] uart: [+3.17ms host +0s virt 0.72s virt from start]   ===================================================================
04:45:52.6252 [DEBUG] uart: [+1.08ms host +0s virt 0.72s virt from start]   PROJECT EXECUTION FAILED