runner.odin 33 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932933934935936937938939940941942943944945946947948949950951952953954955956957958959960961962963964965966967968969970971972973974975976977978979980981982983984985986987988
  1. #+private
  2. package testing
  3. /*
  4. (c) Copyright 2024 Feoramund <[email protected]>.
  5. Made available under Odin's BSD-3 license.
  6. List of contributors:
  7. Ginger Bill: Initial implementation.
  8. Feoramund: Total rewrite.
  9. */
  10. import "base:intrinsics"
  11. import "base:runtime"
  12. import "core:bytes"
  13. @require import "core:encoding/base64"
  14. @require import "core:encoding/json"
  15. import "core:fmt"
  16. import "core:io"
  17. @require import "core:log"
  18. import "core:math/rand"
  19. import "core:mem"
  20. import "core:os"
  21. import "core:slice"
  22. @require import "core:strings"
  23. import "core:sync/chan"
  24. import "core:terminal"
  25. import "core:terminal/ansi"
  26. import "core:thread"
  27. import "core:time"
  28. // Specify how many threads to use when running tests.
  29. TEST_THREADS : int : #config(ODIN_TEST_THREADS, 0)
  30. // Track the memory used by each test.
  31. TRACKING_MEMORY : bool : #config(ODIN_TEST_TRACK_MEMORY, true)
  32. // Always report how much memory is used, even when there are no leaks or bad frees.
  33. ALWAYS_REPORT_MEMORY : bool : #config(ODIN_TEST_ALWAYS_REPORT_MEMORY, false)
  34. // Treat memory leaks and bad frees as errors.
  35. FAIL_ON_BAD_MEMORY : bool : #config(ODIN_TEST_FAIL_ON_BAD_MEMORY, false)
  36. // Specify how much memory each thread allocator starts with.
  37. PER_THREAD_MEMORY : int : #config(ODIN_TEST_THREAD_MEMORY, mem.ROLLBACK_STACK_DEFAULT_BLOCK_SIZE)
  38. // Select a specific set of tests to run by name.
  39. // Each test is separated by a comma and may optionally include the package name.
  40. // This may be useful when running tests on multiple packages with `-all-packages`.
  41. // The format is: `package.test_name,test_name_only,...`
  42. TEST_NAMES : string : #config(ODIN_TEST_NAMES, "")
  43. // Show the fancy animated progress report.
  44. // This requires terminal color support, as well as STDOUT to not be redirected to a file.
  45. FANCY_OUTPUT : bool : #config(ODIN_TEST_FANCY, true)
  46. // Copy failed tests to the clipboard when done.
  47. USE_CLIPBOARD : bool : #config(ODIN_TEST_CLIPBOARD, false)
  48. // How many test results to show at a time per package.
  49. PROGRESS_WIDTH : int : #config(ODIN_TEST_PROGRESS_WIDTH, 24)
  50. // This is the random seed that will be sent to each test.
  51. // If it is unspecified, it will be set to the system cycle counter at startup.
  52. SHARED_RANDOM_SEED : u64 : #config(ODIN_TEST_RANDOM_SEED, 0)
  53. // Set the lowest log level for this test run.
  54. LOG_LEVEL_DEFAULT : string : "debug" when ODIN_DEBUG else "info"
  55. LOG_LEVEL : string : #config(ODIN_TEST_LOG_LEVEL, LOG_LEVEL_DEFAULT)
  56. // Report a message at the info level when a test has changed its state.
  57. LOG_STATE_CHANGES : bool : #config(ODIN_TEST_LOG_STATE_CHANGES, false)
  58. // Show only the most necessary logging information.
  59. USING_SHORT_LOGS : bool : #config(ODIN_TEST_SHORT_LOGS, false)
  60. // Output a report of the tests to the given path.
  61. JSON_REPORT : string : #config(ODIN_TEST_JSON_REPORT, "")
  62. get_log_level :: #force_inline proc() -> runtime.Logger_Level {
  63. when LOG_LEVEL == "debug" { return .Debug } else
  64. when LOG_LEVEL == "info" { return .Info } else
  65. when LOG_LEVEL == "warning" { return .Warning } else
  66. when LOG_LEVEL == "error" { return .Error } else
  67. when LOG_LEVEL == "fatal" { return .Fatal } else {
  68. #panic("Unknown `ODIN_TEST_LOG_LEVEL`: \"" + LOG_LEVEL + "\", possible levels are: \"debug\", \"info\", \"warning\", \"error\", or \"fatal\".")
  69. }
  70. }
  71. @(private) global_log_colors_disabled: bool
  72. @(private) global_ansi_disabled: bool
  73. JSON :: struct {
  74. total: int,
  75. success: int,
  76. duration: time.Duration,
  77. packages: map[string][dynamic]JSON_Test,
  78. }
  79. JSON_Test :: struct {
  80. success: bool,
  81. name: string,
  82. }
  83. end_t :: proc(t: ^T) {
  84. for i := len(t.cleanups)-1; i >= 0; i -= 1 {
  85. #no_bounds_check c := t.cleanups[i]
  86. context = c.ctx
  87. c.procedure(c.user_data)
  88. }
  89. delete(t.cleanups)
  90. t.cleanups = {}
  91. }
  92. when TRACKING_MEMORY && FAIL_ON_BAD_MEMORY {
  93. Task_Data :: struct {
  94. it: Internal_Test,
  95. t: T,
  96. allocator_index: int,
  97. tracking_allocator: ^mem.Tracking_Allocator,
  98. }
  99. } else {
  100. Task_Data :: struct {
  101. it: Internal_Test,
  102. t: T,
  103. allocator_index: int,
  104. }
  105. }
  106. Task_Timeout :: struct {
  107. test_index: int,
  108. at_time: time.Time,
  109. location: runtime.Source_Code_Location,
  110. }
  111. run_test_task :: proc(task: thread.Task) {
  112. data := cast(^Task_Data)(task.data)
  113. setup_task_signal_handler(task.user_index)
  114. chan.send(data.t.channel, Event_New_Test {
  115. test_index = task.user_index,
  116. })
  117. chan.send(data.t.channel, Event_State_Change {
  118. new_state = .Running,
  119. })
  120. context.assertion_failure_proc = test_assertion_failure_proc
  121. logger_options := Default_Test_Logger_Opts
  122. if global_log_colors_disabled {
  123. logger_options -= {.Terminal_Color}
  124. }
  125. context.logger = {
  126. procedure = test_logger_proc,
  127. data = &data.t,
  128. lowest_level = get_log_level(),
  129. options = logger_options,
  130. }
  131. random_generator_state: runtime.Default_Random_State
  132. context.random_generator = {
  133. procedure = runtime.default_random_generator_proc,
  134. data = &random_generator_state,
  135. }
  136. rand.reset(data.t.seed)
  137. free_all(context.temp_allocator)
  138. data.it.p(&data.t)
  139. end_t(&data.t)
  140. when TRACKING_MEMORY && FAIL_ON_BAD_MEMORY {
  141. // NOTE(Feoramund): The simplest way to handle treating memory failures
  142. // as errors is to allow the test task runner to access the tracking
  143. // allocator itself.
  144. //
  145. // This way, it's still able to send up a log message, which will be
  146. // used in the end summary, and it can set the test state to `Failed`
  147. // under the usual conditions.
  148. //
  149. // No outside intervention needed.
  150. memory_leaks := len(data.tracking_allocator.allocation_map)
  151. bad_frees := len(data.tracking_allocator.bad_free_array)
  152. memory_is_in_bad_state := memory_leaks + bad_frees > 0
  153. data.t.error_count += memory_leaks + bad_frees
  154. if memory_is_in_bad_state {
  155. log.errorf("Memory failure in `%s.%s` with %i leak%s and %i bad free%s.",
  156. data.it.pkg, data.it.name,
  157. memory_leaks, "" if memory_leaks == 1 else "s",
  158. bad_frees, "" if bad_frees == 1 else "s")
  159. }
  160. }
  161. new_state : Test_State = .Failed if failed(&data.t) else .Successful
  162. chan.send(data.t.channel, Event_State_Change {
  163. new_state = new_state,
  164. })
  165. }
  166. runner :: proc(internal_tests: []Internal_Test) -> bool {
  167. BATCH_BUFFER_SIZE :: 32 * mem.Kilobyte
  168. POOL_BLOCK_SIZE :: 16 * mem.Kilobyte
  169. CLIPBOARD_BUFFER_SIZE :: 16 * mem.Kilobyte
  170. BUFFERED_EVENTS_PER_CHANNEL :: 16
  171. RESERVED_LOG_MESSAGES :: 64
  172. RESERVED_TEST_FAILURES :: 64
  173. ERROR_STRING_TIMEOUT : string : "Test timed out."
  174. ERROR_STRING_UNKNOWN : string : "Test failed for unknown reasons."
  175. OSC_WINDOW_TITLE : string : ansi.OSC + ansi.WINDOW_TITLE + ";Odin test runner (%i/%i)" + ansi.ST
  176. safe_delete_string :: proc(s: string, allocator := context.allocator) {
  177. // Guard against bad frees on static strings.
  178. switch raw_data(s) {
  179. case raw_data(ERROR_STRING_TIMEOUT), raw_data(ERROR_STRING_UNKNOWN):
  180. return
  181. case:
  182. delete(s, allocator)
  183. }
  184. }
  185. stdout := io.to_writer(os.stream_from_handle(os.stdout))
  186. stderr := io.to_writer(os.stream_from_handle(os.stderr))
  187. // The animations are only ever shown through STDOUT;
  188. // STDERR is used exclusively for logging regardless of error level.
  189. global_log_colors_disabled = !terminal.color_enabled || !terminal.is_terminal(os.stderr)
  190. global_ansi_disabled = !terminal.is_terminal(os.stdout)
  191. should_show_animations := FANCY_OUTPUT && terminal.color_enabled && !global_ansi_disabled
  192. // -- Prepare test data.
  193. alloc_error: mem.Allocator_Error
  194. when TEST_NAMES != "" {
  195. select_internal_tests: [dynamic]Internal_Test
  196. defer delete(select_internal_tests)
  197. {
  198. index_list := TEST_NAMES
  199. for selector in strings.split_iterator(&index_list, ",") {
  200. // Temp allocator is fine since we just need to identify which test it's referring to.
  201. split_selector := strings.split(selector, ".", context.temp_allocator)
  202. found := false
  203. switch len(split_selector) {
  204. case 1:
  205. // Only the test name?
  206. #no_bounds_check name := split_selector[0]
  207. find_test_by_name: for it in internal_tests {
  208. if it.name == name {
  209. found = true
  210. _, alloc_error = append(&select_internal_tests, it)
  211. fmt.assertf(alloc_error == nil, "Error appending to select internal tests: %v", alloc_error)
  212. break find_test_by_name
  213. }
  214. }
  215. case 2:
  216. #no_bounds_check pkg := split_selector[0]
  217. #no_bounds_check name := split_selector[1]
  218. find_test_by_pkg_and_name: for it in internal_tests {
  219. if it.pkg == pkg && it.name == name {
  220. found = true
  221. _, alloc_error = append(&select_internal_tests, it)
  222. fmt.assertf(alloc_error == nil, "Error appending to select internal tests: %v", alloc_error)
  223. break find_test_by_pkg_and_name
  224. }
  225. }
  226. }
  227. if !found {
  228. fmt.wprintfln(stderr, "No test found for the name: %q", selector)
  229. }
  230. }
  231. }
  232. // `-vet` needs parameters to be shadowed by themselves first as an
  233. // explicit declaration, to allow the next line to work.
  234. internal_tests := internal_tests
  235. // Intentional shadow with user-specified tests.
  236. internal_tests = select_internal_tests[:]
  237. }
  238. total_failure_count := 0
  239. total_success_count := 0
  240. total_done_count := 0
  241. total_test_count := len(internal_tests)
  242. // This is strictly for updating the window title when the progress
  243. // report is disabled. We're otherwise able to depend on the call to
  244. // `needs_to_redraw`.
  245. last_done_count := -1
  246. if total_test_count == 0 {
  247. // Exit early.
  248. fmt.wprintln(stdout, "No tests to run.")
  249. return true
  250. }
  251. for it in internal_tests {
  252. // NOTE(Feoramund): The old test runner skipped over tests with nil
  253. // procedures, but I couldn't find any case where they occurred.
  254. // This assert stands to prevent any oversight on my part.
  255. fmt.assertf(it.p != nil, "Test %s.%s has <nil> procedure.", it.pkg, it.name)
  256. }
  257. slice.sort_by(internal_tests, proc(a, b: Internal_Test) -> bool {
  258. if a.pkg == b.pkg {
  259. return a.name < b.name
  260. } else {
  261. return a.pkg < b.pkg
  262. }
  263. })
  264. // -- Set thread count.
  265. when TEST_THREADS == 0 {
  266. thread_count := os.processor_core_count()
  267. } else {
  268. thread_count := max(1, TEST_THREADS)
  269. }
  270. thread_count = min(thread_count, total_test_count)
  271. // -- Allocate.
  272. pool_stack: mem.Rollback_Stack
  273. alloc_error = mem.rollback_stack_init(&pool_stack, POOL_BLOCK_SIZE)
  274. fmt.assertf(alloc_error == nil, "Error allocating memory for thread pool: %v", alloc_error)
  275. defer mem.rollback_stack_destroy(&pool_stack)
  276. pool: thread.Pool
  277. thread.pool_init(&pool, mem.rollback_stack_allocator(&pool_stack), thread_count)
  278. defer thread.pool_destroy(&pool)
  279. task_channels: []Task_Channel = ---
  280. task_channels, alloc_error = make([]Task_Channel, thread_count)
  281. fmt.assertf(alloc_error == nil, "Error allocating memory for update channels: %v", alloc_error)
  282. defer delete(task_channels)
  283. for &task_channel, index in task_channels {
  284. task_channel.channel, alloc_error = chan.create_buffered(Update_Channel, BUFFERED_EVENTS_PER_CHANNEL, context.allocator)
  285. fmt.assertf(alloc_error == nil, "Error allocating memory for update channel #%i: %v", index, alloc_error)
  286. }
  287. defer for &task_channel in task_channels {
  288. chan.destroy(&task_channel.channel)
  289. }
  290. // This buffer is used to batch writes to STDOUT or STDERR, to help reduce
  291. // screen flickering.
  292. batch_buffer: bytes.Buffer
  293. bytes.buffer_init_allocator(&batch_buffer, 0, BATCH_BUFFER_SIZE)
  294. batch_writer := io.to_writer(bytes.buffer_to_stream(&batch_buffer))
  295. defer bytes.buffer_destroy(&batch_buffer)
  296. report: Report = ---
  297. report, alloc_error = make_report(internal_tests)
  298. fmt.assertf(alloc_error == nil, "Error allocating memory for test report: %v", alloc_error)
  299. defer destroy_report(&report)
  300. // We cannot make use of the ANSI save/restore cursor codes, because they
  301. // work by absolute screen coordinates. This will cause unnecessary
  302. // scrollback if we print at the bottom of someone's terminal.
  303. ansi_redraw_string := fmt.aprintf(
  304. // ANSI for "go up N lines then erase the screen from the cursor forward."
  305. ansi.CSI + "%i" + ansi.CPL + ansi.CSI + ansi.ED +
  306. // We'll combine this with the window title format string, since it
  307. // can be printed at the same time.
  308. "%s",
  309. // 1 extra line for the status bar.
  310. 1 + len(report.packages), OSC_WINDOW_TITLE)
  311. assert(len(ansi_redraw_string) > 0, "Error allocating ANSI redraw string.")
  312. defer delete(ansi_redraw_string)
  313. thread_count_status_string: string = ---
  314. {
  315. PADDING :: PROGRESS_COLUMN_SPACING + PROGRESS_WIDTH
  316. unpadded := fmt.tprintf("%i thread%s", thread_count, "" if thread_count == 1 else "s")
  317. thread_count_status_string = fmt.aprintf("%- *[1]s", unpadded, report.pkg_column_len + PADDING)
  318. assert(len(thread_count_status_string) > 0, "Error allocating thread count status string.")
  319. }
  320. defer delete(thread_count_status_string)
  321. task_data_slots: []Task_Data = ---
  322. task_data_slots, alloc_error = make([]Task_Data, thread_count)
  323. fmt.assertf(alloc_error == nil, "Error allocating memory for task data slots: %v", alloc_error)
  324. defer delete(task_data_slots)
  325. // Tests rotate through these allocators as they finish.
  326. task_allocators: []mem.Rollback_Stack = ---
  327. task_allocators, alloc_error = make([]mem.Rollback_Stack, thread_count)
  328. fmt.assertf(alloc_error == nil, "Error allocating memory for task allocators: %v", alloc_error)
  329. defer delete(task_allocators)
  330. when TRACKING_MEMORY {
  331. task_memory_trackers: []mem.Tracking_Allocator = ---
  332. task_memory_trackers, alloc_error = make([]mem.Tracking_Allocator, thread_count)
  333. fmt.assertf(alloc_error == nil, "Error allocating memory for memory trackers: %v", alloc_error)
  334. defer delete(task_memory_trackers)
  335. }
  336. #no_bounds_check for i in 0 ..< thread_count {
  337. alloc_error = mem.rollback_stack_init(&task_allocators[i], PER_THREAD_MEMORY)
  338. fmt.assertf(alloc_error == nil, "Error allocating memory for task allocator #%i: %v", i, alloc_error)
  339. when TRACKING_MEMORY {
  340. mem.tracking_allocator_init(&task_memory_trackers[i], mem.rollback_stack_allocator(&task_allocators[i]))
  341. task_memory_trackers[i].bad_free_callback = mem.tracking_allocator_bad_free_callback_add_to_array
  342. }
  343. }
  344. defer #no_bounds_check for i in 0 ..< thread_count {
  345. when TRACKING_MEMORY {
  346. mem.tracking_allocator_destroy(&task_memory_trackers[i])
  347. }
  348. mem.rollback_stack_destroy(&task_allocators[i])
  349. }
  350. task_timeouts: [dynamic]Task_Timeout = ---
  351. task_timeouts, alloc_error = make([dynamic]Task_Timeout, 0, thread_count)
  352. fmt.assertf(alloc_error == nil, "Error allocating memory for task timeouts: %v", alloc_error)
  353. defer delete(task_timeouts)
  354. failed_test_reason_map: map[int]string = ---
  355. failed_test_reason_map, alloc_error = make(map[int]string, RESERVED_TEST_FAILURES)
  356. fmt.assertf(alloc_error == nil, "Error allocating memory for failed test reasons: %v", alloc_error)
  357. defer delete(failed_test_reason_map)
  358. log_messages: [dynamic]Log_Message = ---
  359. log_messages, alloc_error = make([dynamic]Log_Message, 0, RESERVED_LOG_MESSAGES)
  360. fmt.assertf(alloc_error == nil, "Error allocating memory for log message queue: %v", alloc_error)
  361. defer delete(log_messages)
  362. sorted_failed_test_reasons: [dynamic]int = ---
  363. sorted_failed_test_reasons, alloc_error = make([dynamic]int, 0, RESERVED_TEST_FAILURES)
  364. fmt.assertf(alloc_error == nil, "Error allocating memory for sorted failed test reasons: %v", alloc_error)
  365. defer delete(sorted_failed_test_reasons)
  366. when USE_CLIPBOARD {
  367. clipboard_buffer: bytes.Buffer
  368. bytes.buffer_init_allocator(&clipboard_buffer, 0, CLIPBOARD_BUFFER_SIZE)
  369. defer bytes.buffer_destroy(&clipboard_buffer)
  370. }
  371. when SHARED_RANDOM_SEED == 0 {
  372. shared_random_seed := cast(u64)intrinsics.read_cycle_counter()
  373. } else {
  374. shared_random_seed := SHARED_RANDOM_SEED
  375. }
  376. // -- Setup initial tasks.
  377. // NOTE(Feoramund): This is the allocator that will be used by threads to
  378. // persist log messages past their lifetimes. It has its own variable name
  379. // in the event it needs to be changed from `context.allocator` without
  380. // digging through the source to divine everywhere it is used for that.
  381. shared_log_allocator := context.allocator
  382. logger_options := Default_Test_Logger_Opts - {.Short_File_Path, .Line, .Procedure}
  383. if global_log_colors_disabled {
  384. logger_options -= {.Terminal_Color}
  385. }
  386. context.logger = {
  387. procedure = runner_logger_proc,
  388. data = &log_messages,
  389. lowest_level = get_log_level(),
  390. options = logger_options,
  391. }
  392. run_index: int
  393. setup_tasks: for &data, task_index in task_data_slots {
  394. setup_next_test: for run_index < total_test_count {
  395. #no_bounds_check it := internal_tests[run_index]
  396. defer run_index += 1
  397. data.it = it
  398. data.t.seed = shared_random_seed
  399. #no_bounds_check data.t.channel = chan.as_send(task_channels[task_index].channel)
  400. data.t._log_allocator = shared_log_allocator
  401. data.allocator_index = task_index
  402. #no_bounds_check when TRACKING_MEMORY {
  403. task_allocator := mem.tracking_allocator(&task_memory_trackers[task_index])
  404. when FAIL_ON_BAD_MEMORY {
  405. data.tracking_allocator = &task_memory_trackers[task_index]
  406. }
  407. } else {
  408. task_allocator := mem.rollback_stack_allocator(&task_allocators[task_index])
  409. }
  410. thread.pool_add_task(&pool, task_allocator, run_test_task, &data, run_index)
  411. continue setup_tasks
  412. }
  413. }
  414. // -- Run tests.
  415. setup_signal_handler()
  416. if !global_ansi_disabled {
  417. fmt.wprint(stdout, ansi.CSI + ansi.DECTCEM_HIDE)
  418. }
  419. signals_were_raised := false
  420. if should_show_animations {
  421. redraw_report(stdout, report)
  422. draw_status_bar(stdout, thread_count_status_string, total_done_count, total_test_count)
  423. }
  424. when TEST_THREADS == 0 {
  425. log.infof("Starting test runner with %i thread%s. Set with -define:ODIN_TEST_THREADS=n.",
  426. thread_count,
  427. "" if thread_count == 1 else "s")
  428. } else {
  429. log.infof("Starting test runner with %i thread%s.",
  430. thread_count,
  431. "" if thread_count == 1 else "s")
  432. }
  433. when SHARED_RANDOM_SEED == 0 {
  434. log.infof("The random seed sent to every test is: %v. Set with -define:ODIN_TEST_RANDOM_SEED=n.", shared_random_seed)
  435. } else {
  436. log.infof("The random seed sent to every test is: %v.", shared_random_seed)
  437. }
  438. when TRACKING_MEMORY {
  439. when ALWAYS_REPORT_MEMORY {
  440. log.info("Memory tracking is enabled. Tests will log their memory usage when complete.")
  441. } else {
  442. log.info("Memory tracking is enabled. Tests will log their memory usage if there's an issue.")
  443. }
  444. log.info("< Final Mem/ Total Mem> < Peak Mem> (#Free/Alloc) :: [package.test_name]")
  445. } else {
  446. when ALWAYS_REPORT_MEMORY {
  447. log.warn("ODIN_TEST_ALWAYS_REPORT_MEMORY is true, but ODIN_TEST_TRACK_MEMORY is false.")
  448. }
  449. when FAIL_ON_BAD_MEMORY {
  450. log.warn("ODIN_TEST_FAIL_ON_BAD_MEMORY is true, but ODIN_TEST_TRACK_MEMORY is false.")
  451. }
  452. }
  453. start_time := time.now()
  454. thread.pool_start(&pool)
  455. main_loop: for !thread.pool_is_empty(&pool) {
  456. {
  457. events_pending := thread.pool_num_done(&pool) > 0
  458. if !events_pending {
  459. poll_tasks: for &task_channel in task_channels {
  460. if chan.len(task_channel.channel) > 0 {
  461. events_pending = true
  462. break poll_tasks
  463. }
  464. }
  465. }
  466. if !events_pending {
  467. // Keep the main thread from pegging a core at 100% usage.
  468. time.sleep(1 * time.Microsecond)
  469. }
  470. }
  471. cycle_pool: for task in thread.pool_pop_done(&pool) {
  472. data := cast(^Task_Data)(task.data)
  473. when TRACKING_MEMORY {
  474. #no_bounds_check tracker := &task_memory_trackers[data.allocator_index]
  475. memory_is_in_bad_state := len(tracker.allocation_map) + len(tracker.bad_free_array) > 0
  476. when ALWAYS_REPORT_MEMORY {
  477. should_report := true
  478. } else {
  479. should_report := memory_is_in_bad_state
  480. }
  481. if should_report {
  482. write_memory_report(batch_writer, tracker, data.it.pkg, data.it.name)
  483. when FAIL_ON_BAD_MEMORY {
  484. log.log(.Error if memory_is_in_bad_state else .Info, bytes.buffer_to_string(&batch_buffer))
  485. } else {
  486. log.log(.Warning if memory_is_in_bad_state else .Info, bytes.buffer_to_string(&batch_buffer))
  487. }
  488. bytes.buffer_reset(&batch_buffer)
  489. }
  490. mem.tracking_allocator_reset(tracker)
  491. }
  492. free_all(task.allocator)
  493. if run_index < total_test_count {
  494. #no_bounds_check it := internal_tests[run_index]
  495. defer run_index += 1
  496. data.it = it
  497. data.t.seed = shared_random_seed
  498. data.t.error_count = 0
  499. data.t._fail_now_called = false
  500. thread.pool_add_task(&pool, task.allocator, run_test_task, data, run_index)
  501. }
  502. }
  503. handle_events: for &task_channel in task_channels {
  504. for ev in chan.try_recv(task_channel.channel) {
  505. switch event in ev {
  506. case Event_New_Test:
  507. task_channel.test_index = event.test_index
  508. case Event_State_Change:
  509. #no_bounds_check report.all_test_states[task_channel.test_index] = event.new_state
  510. #no_bounds_check it := internal_tests[task_channel.test_index]
  511. #no_bounds_check pkg := report.packages_by_name[it.pkg]
  512. #partial switch event.new_state {
  513. case .Failed:
  514. if task_channel.test_index not_in failed_test_reason_map {
  515. failed_test_reason_map[task_channel.test_index] = ERROR_STRING_UNKNOWN
  516. }
  517. total_failure_count += 1
  518. total_done_count += 1
  519. case .Successful:
  520. total_success_count += 1
  521. total_done_count += 1
  522. }
  523. when LOG_STATE_CHANGES {
  524. log.infof("Test #%i %s.%s changed state to %v.", task_channel.test_index, it.pkg, it.name, event.new_state)
  525. }
  526. pkg.last_change_state = event.new_state
  527. pkg.last_change_name = it.name
  528. pkg.frame_ready = false
  529. case Event_Set_Fail_Timeout:
  530. _, alloc_error = append(&task_timeouts, Task_Timeout {
  531. test_index = task_channel.test_index,
  532. at_time = event.at_time,
  533. location = event.location,
  534. })
  535. fmt.assertf(alloc_error == nil, "Error appending to task timeouts: %v", alloc_error)
  536. case Event_Log_Message:
  537. _, alloc_error = append(&log_messages, Log_Message {
  538. level = event.level,
  539. text = event.formatted_text,
  540. time = event.time,
  541. allocator = shared_log_allocator,
  542. })
  543. fmt.assertf(alloc_error == nil, "Error appending to log messages: %v", alloc_error)
  544. if event.level >= .Error {
  545. // Save the message for the final summary.
  546. if old_error, ok := failed_test_reason_map[task_channel.test_index]; ok {
  547. safe_delete_string(old_error, shared_log_allocator)
  548. }
  549. failed_test_reason_map[task_channel.test_index] = event.text
  550. } else {
  551. delete(event.text, shared_log_allocator)
  552. }
  553. }
  554. }
  555. }
  556. check_timeouts: for i := len(task_timeouts) - 1; i >= 0; i -= 1 {
  557. #no_bounds_check timeout := &task_timeouts[i]
  558. if time.since(timeout.at_time) < 0 {
  559. continue check_timeouts
  560. }
  561. defer unordered_remove(&task_timeouts, i)
  562. #no_bounds_check if report.all_test_states[timeout.test_index] > .Running {
  563. continue check_timeouts
  564. }
  565. if !thread.pool_stop_task(&pool, timeout.test_index) {
  566. // The task may have stopped a split second after we started
  567. // checking, but we haven't handled the new state yet.
  568. continue check_timeouts
  569. }
  570. #no_bounds_check report.all_test_states[timeout.test_index] = .Failed
  571. #no_bounds_check it := internal_tests[timeout.test_index]
  572. #no_bounds_check pkg := report.packages_by_name[it.pkg]
  573. pkg.frame_ready = false
  574. if old_error, ok := failed_test_reason_map[timeout.test_index]; ok {
  575. safe_delete_string(old_error, shared_log_allocator)
  576. }
  577. failed_test_reason_map[timeout.test_index] = ERROR_STRING_TIMEOUT
  578. total_failure_count += 1
  579. total_done_count += 1
  580. now := time.now()
  581. _, alloc_error = append(&log_messages, Log_Message {
  582. level = .Error,
  583. text = format_log_text(.Error, ERROR_STRING_TIMEOUT, Default_Test_Logger_Opts, timeout.location, now),
  584. time = now,
  585. allocator = context.allocator,
  586. })
  587. fmt.assertf(alloc_error == nil, "Error appending to log messages: %v", alloc_error)
  588. find_task_data_for_timeout: for &data in task_data_slots {
  589. if data.it.pkg == it.pkg && data.it.name == it.name {
  590. end_t(&data.t)
  591. break find_task_data_for_timeout
  592. }
  593. }
  594. }
  595. if should_stop_runner() {
  596. fmt.wprintln(stderr, "\nCaught interrupt signal. Stopping all tests.")
  597. thread.pool_shutdown(&pool)
  598. break main_loop
  599. }
  600. // Because the bounds checking procs send directly to STDERR with
  601. // no way to redirect or handle them, we need to at least try to
  602. // let the user see those messages when using the animated progress
  603. // report. This flag may be set by the block of code below if a
  604. // signal is raised.
  605. //
  606. // It'll be purely by luck if the output is interleaved properly,
  607. // given the nature of non-thread-safe printing.
  608. //
  609. // At worst, if Odin did not print any error for this signal, we'll
  610. // just re-display the progress report. The fatal log error message
  611. // should be enough to clue the user in that something dire has
  612. // occurred.
  613. bypass_progress_overwrite := false
  614. if test_index, reason, ok := should_stop_test(); ok {
  615. passed := reason == .Successful_Stop
  616. #no_bounds_check report.all_test_states[test_index] = .Successful if passed else .Failed
  617. #no_bounds_check it := internal_tests[test_index]
  618. #no_bounds_check pkg := report.packages_by_name[it.pkg]
  619. pkg.frame_ready = false
  620. found := thread.pool_stop_task(&pool, test_index)
  621. fmt.assertf(found, "A signal (%v) was raised to stop test #%i %s.%s, but it was unable to be found.",
  622. reason, test_index, it.pkg, it.name)
  623. // The order this is handled in is a little particular.
  624. task_data: ^Task_Data
  625. find_task_data_for_stop_signal: for &data in task_data_slots {
  626. if data.it.pkg == it.pkg && data.it.name == it.name {
  627. task_data = &data
  628. break find_task_data_for_stop_signal
  629. }
  630. }
  631. fmt.assertf(task_data != nil, "A signal (%v) was raised to stop test #%i %s.%s, but its task data is missing.",
  632. reason, test_index, it.pkg, it.name)
  633. if !passed && !task_data.t._fail_now_called {
  634. if test_index not_in failed_test_reason_map {
  635. // We only write a new error message here if there wasn't one
  636. // already, because the message we can provide based only on
  637. // the signal won't be very useful, whereas asserts and panics
  638. // will provide a user-written error message.
  639. failed_test_reason_map[test_index] = fmt.aprintf("Signal caught: %v", reason, allocator = shared_log_allocator)
  640. log.fatalf("Caught signal to stop test #%i %s.%s for: %v.", test_index, it.pkg, it.name, reason)
  641. }
  642. if should_show_animations {
  643. bypass_progress_overwrite = true
  644. signals_were_raised = true
  645. }
  646. }
  647. end_t(&task_data.t)
  648. if passed {
  649. total_success_count += 1
  650. } else {
  651. total_failure_count += 1
  652. }
  653. total_done_count += 1
  654. }
  655. // -- Redraw.
  656. if should_show_animations {
  657. if len(log_messages) == 0 && !needs_to_redraw(report) {
  658. continue main_loop
  659. }
  660. if !bypass_progress_overwrite {
  661. fmt.wprintf(stdout, ansi_redraw_string, total_done_count, total_test_count)
  662. }
  663. } else {
  664. if total_done_count != last_done_count {
  665. if !global_ansi_disabled {
  666. fmt.wprintf(stdout, OSC_WINDOW_TITLE, total_done_count, total_test_count)
  667. }
  668. last_done_count = total_done_count
  669. }
  670. if len(log_messages) == 0 {
  671. continue main_loop
  672. }
  673. }
  674. // Because each thread has its own messenger channel, log messages
  675. // arrive in chunks that are in-order, but when they're merged with the
  676. // logs from other threads, they become out-of-order.
  677. slice.stable_sort_by(log_messages[:], proc(a, b: Log_Message) -> bool {
  678. return time.diff(a.time, b.time) > 0
  679. })
  680. for message in log_messages {
  681. fmt.wprintln(batch_writer, message.text)
  682. delete(message.text, message.allocator)
  683. }
  684. fmt.wprint(stderr, bytes.buffer_to_string(&batch_buffer))
  685. clear(&log_messages)
  686. bytes.buffer_reset(&batch_buffer)
  687. if should_show_animations {
  688. redraw_report(batch_writer, report)
  689. draw_status_bar(batch_writer, thread_count_status_string, total_done_count, total_test_count)
  690. fmt.wprint(stdout, bytes.buffer_to_string(&batch_buffer))
  691. bytes.buffer_reset(&batch_buffer)
  692. }
  693. }
  694. // -- All tests are complete, or the runner has been interrupted.
  695. // NOTE(Feoramund): If you've arrived here after receiving signal 11 or
  696. // SIGSEGV on the main runner thread, while using a UNIX-like platform,
  697. // there is the possibility that you may have encountered a rare edge case
  698. // involving the joining of threads.
  699. //
  700. // At the time of writing, the thread library is undergoing a rewrite that
  701. // should solve this problem; it is not an issue with the test runner itself.
  702. thread.pool_join(&pool)
  703. finished_in := time.since(start_time)
  704. if !should_show_animations || !terminal.is_terminal(os.stderr) {
  705. // One line to space out the results, since we don't have the status
  706. // bar in plain mode.
  707. fmt.wprintln(batch_writer)
  708. }
  709. fmt.wprintf(batch_writer,
  710. "Finished %i test%s in %v.",
  711. total_done_count,
  712. "" if total_done_count == 1 else "s",
  713. finished_in)
  714. if total_done_count != total_test_count {
  715. not_run_count := total_test_count - total_done_count
  716. message := " %i %s left undone." if global_log_colors_disabled else " " + SGR_READY + "%i" + SGR_RESET + " %s left undone."
  717. fmt.wprintf(batch_writer,
  718. message,
  719. not_run_count,
  720. "test was" if not_run_count == 1 else "tests were")
  721. }
  722. if total_success_count == total_test_count {
  723. message := " %s successful." if global_log_colors_disabled else " %s " + SGR_SUCCESS + "successful." + SGR_RESET
  724. fmt.wprintfln(batch_writer,
  725. message,
  726. "The test was" if total_test_count == 1 else "All tests were")
  727. } else if total_failure_count > 0 {
  728. if total_failure_count == total_test_count {
  729. message := " %s failed." if global_log_colors_disabled else " %s " + SGR_FAILED + "failed." + SGR_RESET
  730. fmt.wprintfln(batch_writer,
  731. message,
  732. "The test" if total_test_count == 1 else "All tests")
  733. } else {
  734. message := " %i test%s failed." if global_log_colors_disabled else " " + SGR_FAILED + "%i" + SGR_RESET + " test%s failed."
  735. fmt.wprintfln(batch_writer,
  736. message,
  737. total_failure_count,
  738. "" if total_failure_count == 1 else "s")
  739. }
  740. for test_index in failed_test_reason_map {
  741. _, alloc_error = append(&sorted_failed_test_reasons, test_index)
  742. fmt.assertf(alloc_error == nil, "Error appending to sorted failed test reasons: %v", alloc_error)
  743. }
  744. slice.sort(sorted_failed_test_reasons[:])
  745. for test_index in sorted_failed_test_reasons {
  746. #no_bounds_check last_error := failed_test_reason_map[test_index]
  747. #no_bounds_check it := internal_tests[test_index]
  748. pkg_and_name := fmt.tprintf("%s.%s", it.pkg, it.name)
  749. fmt.wprintfln(batch_writer, " - %- *[1]s\t%s",
  750. pkg_and_name,
  751. report.pkg_column_len + report.test_column_len,
  752. last_error)
  753. safe_delete_string(last_error, shared_log_allocator)
  754. }
  755. if total_success_count > 0 {
  756. when USE_CLIPBOARD {
  757. clipboard_writer := io.to_writer(bytes.buffer_to_stream(&clipboard_buffer))
  758. fmt.wprint(clipboard_writer, "-define:ODIN_TEST_NAMES=")
  759. for test_index in sorted_failed_test_reasons {
  760. #no_bounds_check it := internal_tests[test_index]
  761. fmt.wprintf(clipboard_writer, "%s.%s,", it.pkg, it.name)
  762. }
  763. encoded_names := base64.encode(bytes.buffer_to_bytes(&clipboard_buffer), allocator = context.temp_allocator)
  764. fmt.wprintf(batch_writer,
  765. ansi.OSC + ansi.CLIPBOARD + ";c;%s" + ansi.ST +
  766. "\nThe name%s of the failed test%s been copied to your clipboard.",
  767. encoded_names,
  768. "" if total_failure_count == 1 else "s",
  769. " has" if total_failure_count == 1 else "s have")
  770. } else {
  771. fmt.wprintf(batch_writer, "\nTo run only the failed test%s, use:\n\t-define:ODIN_TEST_NAMES=",
  772. "" if total_failure_count == 1 else "s")
  773. for test_index in sorted_failed_test_reasons {
  774. #no_bounds_check it := internal_tests[test_index]
  775. fmt.wprintf(batch_writer, "%s.%s,", it.pkg, it.name)
  776. }
  777. fmt.wprint(batch_writer, "\n\nIf your terminal supports OSC 52, you may use -define:ODIN_TEST_CLIPBOARD to have this copied directly to your clipboard.")
  778. }
  779. fmt.wprintln(batch_writer)
  780. }
  781. }
  782. if !global_ansi_disabled {
  783. fmt.wprint(stdout, ansi.CSI + ansi.DECTCEM_SHOW)
  784. }
  785. if should_show_animations {
  786. if signals_were_raised {
  787. fmt.wprintln(batch_writer, `
  788. Signals were raised during this test run. Log messages are likely to have collided with each other.
  789. To partly mitigate this, redirect STDERR to a file or use the -define:ODIN_TEST_FANCY=false option.`)
  790. }
  791. }
  792. fmt.wprintln(stderr, bytes.buffer_to_string(&batch_buffer))
  793. when JSON_REPORT != "" {
  794. json_report: JSON
  795. mode: int
  796. when ODIN_OS != .Windows {
  797. mode = os.S_IRUSR|os.S_IWUSR|os.S_IRGRP|os.S_IROTH
  798. }
  799. json_fd, err := os.open(JSON_REPORT, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, mode)
  800. fmt.assertf(err == nil, "unable to open file %q for writing of JSON report, error: %v", JSON_REPORT, err)
  801. defer os.close(json_fd)
  802. for test, i in report.all_tests {
  803. #no_bounds_check state := report.all_test_states[i]
  804. if test.pkg not_in json_report.packages {
  805. json_report.packages[test.pkg] = {}
  806. }
  807. tests := &json_report.packages[test.pkg]
  808. append(tests, JSON_Test{name = test.name, success = state == .Successful})
  809. }
  810. json_report.total = len(internal_tests)
  811. json_report.success = total_success_count
  812. json_report.duration = finished_in
  813. err := json.marshal_to_writer(os.stream_from_handle(json_fd), json_report, &{ pretty = true })
  814. fmt.assertf(err == nil, "Error writing JSON report: %v", err)
  815. }
  816. return total_success_count == total_test_count
  817. }