tests: replace fprintf() with testlog()

When we move on to TAP, stdout will be reserved for TAP and stderr is for free
chatter. Set up an example that tests should use testlog() instead of fprintf
or printf to chat in the right place.

Most statements were already printing to stderr, so this just makes then a
little shorter. There are also some statements that printed to stdout and are
now corrected.

Signed-off-by: Pekka Paalanen <pekka.paalanen@collabora.com>

tests/input-timestamps-helper.c

@@ -79,7 +79,7 @@ input_timestamp(void *data,
 	timespec_from_proto(timestamp, tv_sec_hi, tv_sec_lo,
 			    tv_nsec);
 
-	fprintf(stderr, "test-client: got input timestamp %ld.%ld\n",
+	testlog("test-client: got input timestamp %ld.%ld\n",
 		timestamp->tv_sec, timestamp->tv_nsec);
 }
 

tests/internal-screenshot-test.c

@@ -76,7 +76,7 @@ TEST(internal_screenshot)
 	bool dump_all_images = true;
 
 	/* Create the client */
-	printf("Creating client for test\n");
+	testlog("Creating client for test\n");
 	client = create_client_and_test_surface(100, 100, 100, 100);
 	assert(client);
 	surface = client->surface->wl_surface;
@@ -106,19 +106,19 @@ TEST(internal_screenshot)
 	wl_surface_commit(surface);
 
 	/* Take a snapshot.  Result will be in screenshot->wl_buffer. */
-	printf("Taking a screenshot\n");
+	testlog("Taking a screenshot\n");
 	screenshot = capture_screenshot_of_output(client);
 	assert(screenshot);
 
 	/* Load good reference image */
 	fname = screenshot_reference_filename("internal-screenshot-good", 0);
-	printf("Loading good reference image %s\n", fname);
+	testlog("Loading good reference image %s\n", fname);
 	reference_good = load_image_from_png(fname);
 	assert(reference_good);
 
 	/* Load bad reference image */
 	fname = screenshot_reference_filename("internal-screenshot-bad", 0);
-	printf("Loading bad reference image %s\n", fname);
+	testlog("Loading bad reference image %s\n", fname);
 	reference_bad = load_image_from_png(fname);
 	assert(reference_bad);
 
@@ -126,7 +126,7 @@ TEST(internal_screenshot)
 	 * We expect this to fail since we use a bad reference image
 	 */
 	match = check_images_match(screenshot->image, reference_bad, NULL);
-	printf("Screenshot %s reference image\n", match? "equal to" : "different from");
+	testlog("Screenshot %s reference image\n", match? "equal to" : "different from");
 	assert(!match);
 	pixman_image_unref(reference_bad);
 
@@ -138,9 +138,9 @@ TEST(internal_screenshot)
 	clip.y = 100;
 	clip.width = 100;
 	clip.height = 100;
-	printf("Clip: %d,%d %d x %d\n", clip.x, clip.y, clip.width, clip.height);
+	testlog("Clip: %d,%d %d x %d\n", clip.x, clip.y, clip.width, clip.height);
 	match = check_images_match(screenshot->image, reference_good, &clip);
-	printf("Screenshot %s reference image in clipped area\n", match? "matches" : "doesn't match");
+	testlog("Screenshot %s reference image in clipped area\n", match? "matches" : "doesn't match");
 	if (!match) {
 		diffimg = visualize_image_difference(screenshot->image, reference_good, &clip);
 		fname = screenshot_output_filename("internal-screenshot-error", 0);
@@ -157,6 +157,6 @@ TEST(internal_screenshot)
 
 	buffer_destroy(screenshot);
 
-	printf("Test complete\n");
+	testlog("Test complete\n");
 	assert(match);
 }

tests/ivi-layout-test-client.c

@@ -99,7 +99,7 @@ runner_destroy(struct runner *runner)
 static void
 runner_run(struct runner *runner, const char *test_name)
 {
-	fprintf(stderr, "weston_test_runner.run(\"%s\")\n", test_name);
+	testlog("weston_test_runner.run(\"%s\")\n", test_name);
 
 	runner->done = 0;
 	weston_test_runner_run(runner->test_runner, test_name);

tests/ivi-shell-app-test.c

@@ -68,5 +68,5 @@ TEST(ivi_application_exists)
 	iviapp = get_ivi_application(client);
 	client_roundtrip(client);
 
-	printf("Successful bind: %p\n", iviapp);
+	testlog("Successful bind: %p\n", iviapp);
 }

tests/presentation-test.c

@@ -188,17 +188,17 @@ feedback_print(struct feedback *fb)
 
 	switch (fb->result) {
 	case FB_PENDING:
-		printf("pending");
+		testlog("pending");
 		return;
 	case FB_DISCARDED:
-		printf("discarded");
+		testlog("discarded");
 		return;
 	case FB_PRESENTED:
 		break;
 	}
 
 	pflags_to_str(fb->flags, str, sizeof str);
-	printf("presented %lld.%09lld, refresh %u us, [%s] seq %" PRIu64,
+	testlog("presented %lld.%09lld, refresh %u us, [%s] seq %" PRIu64,
 		(long long)fb->time.tv_sec, (long long)fb->time.tv_nsec,
 		fb->refresh_nsec / 1000, str, fb->seq);
 }
@@ -230,9 +230,9 @@ TEST(test_presentation_feedback_simple)
 
 	feedback_wait(fb);
 
-	printf("%s feedback:", __func__);
+	testlog("%s feedback:", __func__);
 	feedback_print(fb);
-	printf("\n");
+	testlog("\n");
 
 	feedback_destroy(fb);
 }

tests/subsurface-shot-test.c

@@ -144,7 +144,7 @@ check_screen(struct client *client,
 	assert(shot);
 
 	match = check_images_match(shot->image, ref, clip);
-	printf("ref %s vs. shot %s: %s\n", ref_fname, shot_fname,
+	testlog("ref %s vs. shot %s: %s\n", ref_fname, shot_fname,
 		match ? "PASS" : "FAIL");
 
 	write_image_as_png(shot->image, shot_fname);

tests/subsurface-test.c

@@ -694,11 +694,11 @@ destroy_permu_object(struct wl_surface **surfs,
 	int h = (i + 1) / 2;
 
 	if (i & 1) {
-		fprintf(stderr, " [sub  %2d]", h);
+		testlog(" [sub  %2d]", h);
 		wl_subsurface_destroy(subs[h]);
 		subs[h] = NULL;
 	} else {
-		fprintf(stderr, " [surf %2d]", h);
+		testlog(" [surf %2d]", h);
 		wl_surface_destroy(surfs[h]);
 		surfs[h] = NULL;
 	}
@@ -736,15 +736,15 @@ TEST(test_subsurface_destroy_permutations)
 
 		create_subsurface_tree(client, surfs, subs, test_size);
 
-		fprintf(stderr, "permu");
+		testlog("permu");
 
 		for (i = 0; i < NSTEPS; i++)
-			fprintf(stderr, " %2d", per.cnt[i]);
+			testlog(" %2d", per.cnt[i]);
 
 		for (i = 0; i < NSTEPS; i++)
 			destroy_permu_object(surfs, subs, per.cnt[i]);
 
-		fprintf(stderr, "\n");
+		testlog("\n");
 		client_roundtrip(client);
 
 		destroy_subsurface_tree(surfs, subs, test_size);
@@ -752,5 +752,5 @@ TEST(test_subsurface_destroy_permutations)
 	}
 
 	client_roundtrip(client);
-	fprintf(stderr, "tried %d destroy permutations\n", counter);
+	testlog("tried %d destroy permutations\n", counter);
 }

tests/text-test.c

@@ -112,7 +112,7 @@ text_input_enter(void *data,
 {
 	struct text_input_state *state = data;
 
-	fprintf(stderr, "%s\n", __FUNCTION__);
+	testlog("%s\n", __FUNCTION__);
 
 	state->activated += 1;
 }

tests/viewporter-test.c

@@ -125,7 +125,7 @@ TEST_P(test_viewporter_bad_source_rect, bad_source_rect_args)
 
 	vp = create_viewport(client);
 
-	fprintf(stderr, "wp_viewport.set_source x=%d, y=%d, w=%d, h=%d\n",
+	testlog("wp_viewport.set_source x=%d, y=%d, w=%d, h=%d\n",
 		args->x, args->y, args->w, args->h);
 	set_source(vp, args->x, args->y, args->w, args->h);
 
@@ -170,8 +170,7 @@ TEST_P(test_viewporter_bad_destination_size, bad_destination_args)
 
 	vp = create_viewport(client);
 
-	fprintf(stderr, "wp_viewport.set_destination w=%d, h=%d\n",
-		args->w, args->h);
+	testlog("wp_viewport.set_destination w=%d, h=%d\n", args->w, args->h);
 	wp_viewport_set_destination(vp, args->w, args->h);
 
 	expect_protocol_error(client, &wp_viewport_interface,
@@ -216,7 +215,7 @@ TEST_P(test_viewporter_non_integer_destination_size, nonint_destination_args)
 
 	vp = create_viewport(client);
 
-	fprintf(stderr, "non-integer size w=%f, h=%f\n",
+	testlog("non-integer size w=%f, h=%f\n",
 		wl_fixed_to_double(args->w), wl_fixed_to_double(args->h));
 	wp_viewport_set_source(vp, 5, 6, args->w, args->h);
 	wp_viewport_set_destination(vp, -1, -1);
@@ -285,12 +284,12 @@ setup_source_vs_buffer(struct client *client,
 	surf = client->surface->wl_surface;
 	vp = create_viewport(client);
 
-	fprintf(stderr, "surface %dx%d\n",
+	testlog("surface %dx%d\n",
 		get_surface_width(client->surface,
 				  args->buffer_scale, args->buffer_transform),
 		get_surface_height(client->surface,
 				   args->buffer_scale, args->buffer_transform));
-	fprintf(stderr, "source x=%f, y=%f, w=%f, h=%f; "
+	testlog("source x=%f, y=%f, w=%f, h=%f; "
 		"buffer scale=%d, transform=%d\n",
 		wl_fixed_to_double(args->x), wl_fixed_to_double(args->y),
 		wl_fixed_to_double(args->w), wl_fixed_to_double(args->h),

tests/weston-test-client-helper.c

@@ -130,7 +130,7 @@ pointer_handle_enter(void *data, struct wl_pointer *wl_pointer,
 	pointer->x = wl_fixed_to_int(x);
 	pointer->y = wl_fixed_to_int(y);
 
-	fprintf(stderr, "test-client: got pointer enter %d %d, surface %p\n",
+	testlog("test-client: got pointer enter %d %d, surface %p\n",
 		pointer->x, pointer->y, pointer->focus);
 }
 
@@ -142,7 +142,7 @@ pointer_handle_leave(void *data, struct wl_pointer *wl_pointer,
 
 	pointer->focus = NULL;
 
-	fprintf(stderr, "test-client: got pointer leave, surface %p\n",
+	testlog("test-client: got pointer leave, surface %p\n",
 		wl_surface ? wl_surface_get_user_data(wl_surface) : NULL);
 }
 
@@ -158,7 +158,7 @@ pointer_handle_motion(void *data, struct wl_pointer *wl_pointer,
 	pointer->motion_time_timespec = pointer->input_timestamp;
 	pointer->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got pointer motion %d %d\n",
+	testlog("test-client: got pointer motion %d %d\n",
 		pointer->x, pointer->y);
 }
 
@@ -175,8 +175,7 @@ pointer_handle_button(void *data, struct wl_pointer *wl_pointer,
 	pointer->button_time_timespec = pointer->input_timestamp;
 	pointer->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got pointer button %u %u\n",
-		button, state);
+	testlog("test-client: got pointer button %u %u\n", button, state);
 }
 
 static void
@@ -191,21 +190,21 @@ pointer_handle_axis(void *data, struct wl_pointer *wl_pointer,
 	pointer->axis_time_timespec = pointer->input_timestamp;
 	pointer->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got pointer axis %u %f\n",
+	testlog("test-client: got pointer axis %u %f\n",
 		axis, wl_fixed_to_double(value));
 }
 
 static void
 pointer_handle_frame(void *data, struct wl_pointer *wl_pointer)
 {
-	fprintf(stderr, "test-client: got pointer frame\n");
+	testlog("test-client: got pointer frame\n");
 }
 
 static void
 pointer_handle_axis_source(void *data, struct wl_pointer *wl_pointer,
 			     uint32_t source)
 {
-	fprintf(stderr, "test-client: got pointer axis source %u\n", source);
+	testlog("test-client: got pointer axis source %u\n", source);
 }
 
 static void
@@ -219,15 +218,14 @@ pointer_handle_axis_stop(void *data, struct wl_pointer *wl_pointer,
 	pointer->axis_stop_time_timespec = pointer->input_timestamp;
 	pointer->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got pointer axis stop %u\n", axis);
+	testlog("test-client: got pointer axis stop %u\n", axis);
 }
 
 static void
 pointer_handle_axis_discrete(void *data, struct wl_pointer *wl_pointer,
 			     uint32_t axis, int32_t value)
 {
-	fprintf(stderr, "test-client: got pointer axis discrete %u %d\n",
-		axis, value);
+	testlog("test-client: got pointer axis discrete %u %d\n", axis, value);
 }
 
 static const struct wl_pointer_listener pointer_listener = {
@@ -248,7 +246,7 @@ keyboard_handle_keymap(void *data, struct wl_keyboard *wl_keyboard,
 {
 	close(fd);
 
-	fprintf(stderr, "test-client: got keyboard keymap\n");
+	testlog("test-client: got keyboard keymap\n");
 }
 
 static void
@@ -263,7 +261,7 @@ keyboard_handle_enter(void *data, struct wl_keyboard *wl_keyboard,
 	else
 		keyboard->focus = NULL;
 
-	fprintf(stderr, "test-client: got keyboard enter, surface %p\n",
+	testlog("test-client: got keyboard enter, surface %p\n",
 		keyboard->focus);
 }
 
@@ -275,7 +273,7 @@ keyboard_handle_leave(void *data, struct wl_keyboard *wl_keyboard,
 
 	keyboard->focus = NULL;
 
-	fprintf(stderr, "test-client: got keyboard leave, surface %p\n",
+	testlog("test-client: got keyboard leave, surface %p\n",
 		wl_surface ? wl_surface_get_user_data(wl_surface) : NULL);
 }
 
@@ -292,7 +290,7 @@ keyboard_handle_key(void *data, struct wl_keyboard *wl_keyboard,
 	keyboard->key_time_timespec = keyboard->input_timestamp;
 	keyboard->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got keyboard key %u %u\n", key, state);
+	testlog("test-client: got keyboard key %u %u\n", key, state);
 }
 
 static void
@@ -308,7 +306,7 @@ keyboard_handle_modifiers(void *data, struct wl_keyboard *wl_keyboard,
 	keyboard->mods_locked = mods_locked;
 	keyboard->group = group;
 
-	fprintf(stderr, "test-client: got keyboard modifiers %u %u %u %u\n",
+	testlog("test-client: got keyboard modifiers %u %u %u %u\n",
 		mods_depressed, mods_latched, mods_locked, group);
 }
 
@@ -321,8 +319,7 @@ keyboard_handle_repeat_info(void *data, struct wl_keyboard *wl_keyboard,
 	keyboard->repeat_info.rate = rate;
 	keyboard->repeat_info.delay = delay;
 
-	fprintf(stderr, "test-client: got keyboard repeat_info %d %d\n",
-		rate, delay);
+	testlog("test-client: got keyboard repeat_info %d %d\n", rate, delay);
 }
 
 static const struct wl_keyboard_listener keyboard_listener = {
@@ -349,7 +346,7 @@ touch_handle_down(void *data, struct wl_touch *wl_touch,
 	touch->down_time_timespec = touch->input_timestamp;
 	touch->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got touch down %d %d, surf: %p, id: %d\n",
+	testlog("test-client: got touch down %d %d, surf: %p, id: %d\n",
 		touch->down_x, touch->down_y, surface, id);
 }
 
@@ -363,7 +360,7 @@ touch_handle_up(void *data, struct wl_touch *wl_touch,
 	touch->up_time_timespec = touch->input_timestamp;
 	touch->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got touch up, id: %d\n", id);
+	testlog("test-client: got touch up, id: %d\n", id);
 }
 
 static void
@@ -378,7 +375,7 @@ touch_handle_motion(void *data, struct wl_touch *wl_touch,
 	touch->motion_time_timespec = touch->input_timestamp;
 	touch->input_timestamp = (struct timespec) { 0 };
 
-	fprintf(stderr, "test-client: got touch motion, %d %d, id: %d\n",
+	testlog("test-client: got touch motion, %d %d, id: %d\n",
 		touch->x, touch->y, id);
 }
 
@@ -389,7 +386,7 @@ touch_handle_frame(void *data, struct wl_touch *wl_touch)
 
 	++touch->frame_no;
 
-	fprintf(stderr, "test-client: got touch frame (%d)\n", touch->frame_no);
+	testlog("test-client: got touch frame (%d)\n", touch->frame_no);
 }
 
 static void
@@ -399,7 +396,7 @@ touch_handle_cancel(void *data, struct wl_touch *wl_touch)
 
 	++touch->cancel_no;
 
-	fprintf(stderr, "test-client: got touch cancel (%d)\n", touch->cancel_no);
+	testlog("test-client: got touch cancel (%d)\n", touch->cancel_no);
 }
 
 static const struct wl_touch_listener touch_listener = {
@@ -418,8 +415,7 @@ surface_enter(void *data,
 
 	surface->output = wl_output_get_user_data(output);
 
-	fprintf(stderr, "test-client: got surface enter output %p\n",
-		surface->output);
+	testlog("test-client: got surface enter output %p\n", surface->output);
 }
 
 static void
@@ -430,7 +426,7 @@ surface_leave(void *data,
 
 	surface->output = NULL;
 
-	fprintf(stderr, "test-client: got surface leave output %p\n",
+	testlog("test-client: got surface leave output %p\n",
 		wl_output_get_user_data(output));
 }
 
@@ -536,7 +532,7 @@ test_handle_pointer_position(void *data, struct weston_test *weston_test,
 	test->pointer_x = wl_fixed_to_int(x);
 	test->pointer_y = wl_fixed_to_int(y);
 
-	fprintf(stderr, "test-client: got global pointer %d %d\n",
+	testlog("test-client: got global pointer %d %d\n",
 		test->pointer_x, test->pointer_y);
 }
 
@@ -545,7 +541,7 @@ test_handle_capture_screenshot_done(void *data, struct weston_test *weston_test)
 {
 	struct test *test = data;
 
-	printf("Screenshot has been captured\n");
+	testlog("Screenshot has been captured\n");
 	test->buffer_copy_done = 1;
 }
 
@@ -639,8 +635,7 @@ seat_handle_capabilities(void *data, struct wl_seat *seat,
 	if (input->seat_name && strcmp(input->seat_name, "test-seat") == 0)
 		input_update_devices(input);
 
-	fprintf(stderr, "test-client: got seat %p capabilities: %x\n",
-		input, caps);
+	testlog("test-client: got seat %p capabilities: %x\n", input, caps);
 }
 
 static void
@@ -660,8 +655,7 @@ seat_handle_name(void *data, struct wl_seat *seat, const char *name)
 		input->client->input = input;
 	}
 
-	fprintf(stderr, "test-client: got seat %p name: \'%s\'\n",
-		input, name);
+	testlog("test-client: got seat %p name: \'%s\'\n", input, name);
 }
 
 static const struct wl_seat_listener seat_listener = {
@@ -877,8 +871,7 @@ expect_protocol_error(struct client *client,
 
 	/* check error */
 	if (errcode != code) {
-		fprintf(stderr, "Should get error code %d but got %d\n",
-			code, errcode);
+		testlog("Should get error code %d but got %d\n", code, errcode);
 		failed = 1;
 	}
 
@@ -886,18 +879,18 @@ expect_protocol_error(struct client *client,
 	assert(interface);
 
 	if (strcmp(intf->name, interface->name) != 0) {
-		fprintf(stderr, "Should get interface '%s' but got '%s'\n",
+		testlog("Should get interface '%s' but got '%s'\n",
 			intf->name, interface->name);
 		failed = 1;
 	}
 
 	if (failed) {
-		fprintf(stderr, "Expected other protocol error\n");
+		testlog("Expected other protocol error\n");
 		abort();
 	}
 
 	/* all OK */
-	fprintf(stderr, "Got expected protocol error on '%s' (object id: %d) "
+	testlog("Got expected protocol error on '%s' (object id: %d) "
 		"with code %d\n", interface->name, id, errcode);
 }
 
@@ -1337,7 +1330,7 @@ write_image_as_png(pixman_image_t *image, const char *fname)
 
 	status = cairo_surface_write_to_png(cairo_surface, fname);
 	if (status != CAIRO_STATUS_SUCCESS) {
-		fprintf(stderr, "Failed to save image '%s': %s\n", fname,
+		testlog("Failed to save image '%s': %s\n", fname,
 			cairo_status_to_string(status));
 
 		return false;
@@ -1407,7 +1400,8 @@ load_image_from_png(const char *fname)
 	cairo_surface_flush(reference_cairo_surface);
 	status = cairo_surface_status(reference_cairo_surface);
 	if (status != CAIRO_STATUS_SUCCESS) {
-		printf("Could not open %s: %s\n", fname, cairo_status_to_string(status));
+		testlog("Could not open %s: %s\n", fname,
+			cairo_status_to_string(status));
 		cairo_surface_destroy(reference_cairo_surface);
 		return NULL;
 	}

tests/weston-test-runner.c

@@ -50,6 +50,16 @@ get_test_name(void)
 	return test_name_;
 }
 
+void
+testlog(const char *fmt, ...)
+{
+	va_list argp;
+
+	va_start(argp, fmt);
+	vfprintf(stderr, fmt, argp);
+	va_end(argp);
+}
+
 static const struct weston_test *
 find_test(const char *name)
 {

tests/weston-test-runner.h

@@ -31,6 +31,7 @@
 
 #include <stdlib.h>
 
+#include <wayland-util.h>
 #include "shared/helpers.h"
 
 #ifdef NDEBUG
@@ -80,6 +81,9 @@ struct weston_test {
 #define TEST_P(name, data) ARG_TEST(name, 0, data)
 #define FAIL_TEST_P(name, data) ARG_TEST(name, 1, data)
 
+void
+testlog(const char *fmt, ...) WL_PRINTF(1, 2);
+
 /**
  * Get the test name string with counter
  *