runner.odin 30 KB

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