From: Matthias Clasen Date: Sat, 6 May 2023 13:00:27 +0000 (-0400) Subject: ci: Improve headless test logging X-Git-Tag: archive/raspbian/4.12.3+ds-1+rpi1~1^2^2^2~22^2~1^2~300^2~1 X-Git-Url: https://dgit.raspbian.org/?a=commitdiff_plain;h=c9b0ca0de7854e7148ff26614d4b6020cd80fe7d;p=gtk4.git ci: Improve headless test logging --- diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index 657ddd4fca..95bfa130b5 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -70,6 +70,7 @@ style-check-diff: - "${CI_PROJECT_DIR}/_build/testsuite/tools/output/*/*" - "${CI_PROJECT_DIR}/_build/testsuite/gsk/compare/*/*/*.png" - "${CI_PROJECT_DIR}/_build/testsuite/css/output/*/*.syscap" + - "${CI_PROJECT_DIR}/_build/testsuite/headless/*/*.log" - "${CI_PROJECT_DIR}/_build_hello/meson-logs" cache: key: "$CI_JOB_NAME" diff --git a/testsuite/headless/headless-input-tests.py b/testsuite/headless/headless-input-tests.py index d09d162cad..f291d723b8 100644 --- a/testsuite/headless/headless-input-tests.py +++ b/testsuite/headless/headless-input-tests.py @@ -24,12 +24,17 @@ loop = None def quit_cb(loop): loop.quit() + print('timed out while waiting') def wait(millis): global loop + before = GLib.get_monotonic_time() loop = GLib.MainLoop() GLib.timeout_add(millis, quit_cb, loop) loop.run() + if verbose: + time = (GLib.get_monotonic_time() - before) / 1000 + print(f'waited for {time} milliseconds') display = None window = None @@ -41,10 +46,10 @@ def key_pressed_cb (controller, keyval, keycode, state): if verbose: print(f'got key press: {keyval}, state {state}') - assert expected_change != None, "Unexpected key press" - assert expected_change['type'] == 'press', "Key press event expected" - assert keyval == expected_change['keyval'], "Unexpected keyval in key press event" - assert state == expected_change['state'], "Unexpected state in key press event" + assert expected_change != None, 'Unexpected key press' + assert expected_change['type'] == 'press', 'Key press event expected' + assert keyval == expected_change['keyval'], 'Unexpected keyval in key press event' + assert state == expected_change['state'], 'Unexpected state in key press event' expected_change = None loop.quit() @@ -55,10 +60,10 @@ def key_released_cb (controller, keyval, keycode, state): if verbose: print(f'got key release: {keyval}, state {state}') - assert expected_change != None, "Unexpected key release" - assert expected_change['type'] == 'release', "Key release event expected" - assert keyval == expected_change['keyval'], "Unexpected keyval in key release event" - assert state == expected_change['state'], "Unexpected state in key release event" + assert expected_change != None, 'Unexpected key release' + assert expected_change['type'] == 'release', 'Key release event expected' + assert keyval == expected_change['keyval'], 'Unexpected keyval in key release event' + assert state == expected_change['state'], 'Unexpected state in key release event' expected_change = None loop.quit() @@ -70,9 +75,9 @@ def motion_cb (controller, x, y): if verbose: print(f'got motion: {x}, {y}') if expected_change != None: - assert expected_change['type'] == 'motion', "Motion event expected" - assert x == expected_change['x'], "Unexpected x coord in motion event" - assert y == expected_change['y'], "Unexpected y coord in motion event" + assert expected_change['type'] == 'motion', 'Motion event expected' + assert x == expected_change['x'], 'Unexpected x coord in motion event' + assert y == expected_change['y'], 'Unexpected y coord in motion event' expected_change = None loop.quit() @@ -82,10 +87,10 @@ def enter_cb (controller, x, y): if verbose: print(f'got enter: {x}, {y}') - assert expected_change != None, "Unexpected enter" - assert expected_change['type'] == 'enter', "Enter event expected" - assert x == expected_change['x'], "Unexpected x coord in enter event" - assert y == expected_change['y'], "Unexpected y coord in enter event" + assert expected_change != None, 'Unexpected enter' + assert expected_change['type'] == 'enter', 'Enter event expected' + assert x == expected_change['x'], 'Unexpected x coord in enter event' + assert y == expected_change['y'], 'Unexpected y coord in enter event' expected_change = None loop.quit() @@ -96,11 +101,11 @@ def pressed_cb(controller, n, x, y): if verbose: print(f'got pressed') - assert expected_change != None, "Unexpected event" - assert expected_change['type'] == 'press', "Button press expected" - assert expected_change['button'] == controller.get_current_button(), "Unexpected button pressed" - assert x == expected_change['x'], "Unexpected x coord in motion event" - assert y == expected_change['y'], "Unexpected y coord in motion event" + assert expected_change != None, 'Unexpected event' + assert expected_change['type'] == 'press', 'Button press expected' + assert expected_change['button'] == controller.get_current_button(), 'Unexpected button pressed' + assert x == expected_change['x'], 'Unexpected x coord in motion event' + assert y == expected_change['y'], 'Unexpected y coord in motion event' expected_change = None loop.quit() @@ -111,8 +116,8 @@ def released_cb(controller, n, x, y): if verbose: print(f'got released') - assert expected_change != None, "Unexpected event" - assert expected_change['type'] == 'release', "Button release expected" + assert expected_change != None, 'Unexpected event' + assert expected_change['type'] == 'release', 'Button release expected' expected_change = None loop.quit() @@ -125,7 +130,7 @@ def expect_key_press(keyval, state, timeout): 'state' : state } wait(timeout) - assert expected_change == None, "Expected event did not happen" + assert expected_change == None, 'Expected event did not happen' def expect_key_release(keyval, state, timeout): global expected_change @@ -135,7 +140,7 @@ def expect_key_release(keyval, state, timeout): 'state' : state } wait(timeout) - assert expected_change == None, "Expected event did not happen" + assert expected_change == None, 'Expected event did not happen' def expect_motion(x, y, timeout): global expected_change @@ -145,7 +150,7 @@ def expect_motion(x, y, timeout): 'y' : y } wait(timeout) - assert expected_change == None, "Expected event did not happen" + assert expected_change == None, 'Expected event did not happen' def expect_enter(x, y, timeout): global expected_change @@ -155,7 +160,7 @@ def expect_enter(x, y, timeout): 'y' : y } wait(timeout) - assert expected_change == None, "Expected event did not happen" + assert expected_change == None, 'Expected event did not happen' def expect_button_press(button, x, y, timeout): global expected_change @@ -166,7 +171,7 @@ def expect_button_press(button, x, y, timeout): 'y' : y } wait(timeout) - assert expected_change == None, "Button press did not arrive" + assert expected_change == None, 'Button press did not arrive' def expect_button_release(button, x, y, timeout): global expected_change @@ -177,7 +182,7 @@ def expect_button_release(button, x, y, timeout): 'y' : y } wait(timeout) - assert expected_change == None, "Button release did not arrive" + assert expected_change == None, 'Button release did not arrive' def got_active(object, pspec): global loop @@ -220,9 +225,9 @@ def launch_observer(): wait(2000) - assert window.is_active(), "Observer not active" - assert window.get_width() == 1024, "Window not maximized" - assert window.get_height() == 768, "Window not maximized" + assert window.is_active(), 'Observer not active' + assert window.get_width() == 1024, 'Window not maximized' + assert window.get_height() == 768, 'Window not maximized' # we need to wait out the map animation, or pointer coords will be off wait(1000) @@ -265,6 +270,9 @@ def pointer_move(x, y): def basic_keyboard_tests(): try: + if verbose: + print('Starting basic keyboard tests') + launch_observer() key_press(Gdk.KEY_a) @@ -287,11 +295,14 @@ def basic_keyboard_tests(): stop_observer() except AssertionError as e: - print("Error in basic_keyboard_tests: {0}".format(e)) + print(f'Error in basic_keyboard_tests: {e}') terminate() def basic_pointer_tests(): try: + if verbose: + print('Starting basic pointer tests') + pointer_move(-100.0, -100.0) launch_observer() @@ -313,7 +324,7 @@ def basic_pointer_tests(): stop_observer() except AssertionError as e: - print("Error in basic_pointer_tests: {0}".format(e)) + print(f'Error in basic_pointer_tests: {e}') terminate() ds_window = None @@ -324,9 +335,9 @@ def drag_begin(controller, drag): global loop if verbose: - print(f'got drag begin') - assert expected_change != None, "Unexpected drag begin" - assert expected_change['type'] == 'drag', "Drag begin expected" + print('got drag begin') + assert expected_change != None, 'Unexpected drag begin' + assert expected_change['type'] == 'drag', 'Drag begin expected' expected_change = None loop.quit() @@ -362,9 +373,9 @@ def launch_drag_source(value): wait(2000) - assert ds_window.is_active(), "drag source not active" - assert ds_window.get_width() == 1024, "Window not maximized" - assert ds_window.get_height() == 768, "Window not maximized" + assert ds_window.is_active(), 'drag source not active' + assert ds_window.get_width() == 1024, 'Window not maximized' + assert ds_window.get_height() == 768, 'Window not maximized' # we need to wait out the map animation, or pointer coords will be off wait(1000) @@ -382,9 +393,9 @@ def do_drop(controller, value, x, y): if verbose: print(f'got drop {value}') - assert expected_change != None, "Unexpected drop begin" - assert expected_change['type'] == 'drop', "Drop expected" - assert expected_change['value'] == value, "Unexpected value dropped" + assert expected_change != None, 'Unexpected drop begin' + assert expected_change['type'] == 'drop', 'Drop expected' + assert expected_change['value'] == value, 'Unexpected value dropped' expected_change = None loop.quit() @@ -412,9 +423,9 @@ def launch_drop_target(): wait(2000) - assert dt_window.is_active(), "drop target not active" - assert dt_window.get_width() == 1024, "Window not maximized" - assert dt_window.get_height() == 768, "Window not maximized" + assert dt_window.is_active(), 'drop target not active' + assert dt_window.get_width() == 1024, 'Window not maximized' + assert dt_window.get_height() == 768, 'Window not maximized' # we need to wait out the map animation, or pointer coords will be off wait(1000) @@ -430,7 +441,7 @@ def expect_drag(timeout): 'type' : 'drag', } wait(timeout) - assert expected_change == None, "DND operation not started" + assert expected_change == None, 'DND operation not started' def expect_drop(value, timeout): global expected_change @@ -439,10 +450,13 @@ def expect_drop(value, timeout): 'value' : value } wait(timeout) - assert expected_change == None, "Drop has not happened" + assert expected_change == None, 'Drop has not happened' def dnd_tests(): try: + if verbose: + print('Starting dnd tests') + pointer_move(-100, -100) launch_drag_source('abc') @@ -466,12 +480,17 @@ def dnd_tests(): stop_drop_target() stop_drag_source() except AssertionError as e: - print("Error in dnd_tests: {0}".format(e)) + print(f'Error in dnd_tests: {e}') terminate() def session_closed_cb(): print('Session closed') +def run_commands(): + basic_keyboard_tests() + basic_pointer_tests() + dnd_tests() + def mutter_appeared(name): global remote_desktop global session @@ -479,13 +498,13 @@ def mutter_appeared(name): global done if verbose: - print("mutter appeared on the bus") + print('mutter appeared on the bus') remote_desktop = bus.get('org.gnome.Mutter.RemoteDesktop', '/org/gnome/Mutter/RemoteDesktop') device_types = remote_desktop.Get('org.gnome.Mutter.RemoteDesktop', 'SupportedDeviceTypes') - assert device_types & 1 == 1, "No keyboard" - assert device_types & 2 == 2, "No pointer" + assert device_types & 1 == 1, 'No keyboard' + assert device_types & 2 == 2, 'No pointer' screen_cast = bus.get('org.gnome.Mutter.ScreenCast', '/org/gnome/Mutter/ScreenCast') @@ -505,19 +524,19 @@ def mutter_appeared(name): key_release(Gdk.KEY_Control_L) pointer_move(-100, -100) - basic_keyboard_tests() - basic_pointer_tests() - dnd_tests() + run_commands() session.Stop() + if verbose: + print('Done running commands, exiting...') done = True def mutter_vanished(): global done if remote_desktop != None: if verbose: - print("mutter left the bus") + print('mutter left the bus') done = True bus = SessionBus() diff --git a/testsuite/headless/headless-monitor-tests.py b/testsuite/headless/headless-monitor-tests.py index c4d62cb0c0..fa8fb5422c 100644 --- a/testsuite/headless/headless-monitor-tests.py +++ b/testsuite/headless/headless-monitor-tests.py @@ -26,6 +26,9 @@ def terminate(): def stream_added_closure(name): def stream_added(node_id): + if verbose: + print('pipewire stream added') + monitor = monitors[name]; freq = monitor['freq']; @@ -36,7 +39,7 @@ def stream_added_closure(name): # Use gstreamer out-of-process, since the gst gl support gets # itself into a twist with its wayland connection when monitors # disappear - pipeline_desc = f'gst-launch-1.0 --verbose pipewiresrc path={node_id} ! video/x-raw,max-framerate={freq}/1,width={width},height={height} ! videoconvert ! glimagesink' + pipeline_desc = f'gst-launch-1.0 pipewiresrc path={node_id} ! video/x-raw,max-framerate={freq}/1,width={width},height={height} ! videoconvert ! glimagesink' # >& gstreamer-monitor.log' if verbose: print(f'launching {pipeline_desc}') monitor['pipeline'] = subprocess.Popen([pipeline_desc], shell=True) @@ -49,11 +52,11 @@ def add_monitor(name, width, height, scale, freq): session_path = screen_cast.CreateSession({}) session = bus.get('org.gnome.Mutter.ScreenCast', session_path) monitors[name] = { - "session": session, - "width": width, - "height": height, - "scale": scale, - "freq": freq + 'session': session, + 'width': width, + 'height': height, + 'scale': scale, + 'freq': freq } stream_path = session.RecordVirtual({}) stream = bus.get('org.gnome.Mutter.ScreenCast', stream_path) @@ -70,7 +73,7 @@ def remove_monitor(name): session = monitor['session'] session.Stop() except KeyError: - print("failed to remove monitor") + print('failed to remove monitor') monitors[name] = None expected_change = None @@ -78,23 +81,28 @@ loop = None def quit_cb(loop): loop.quit() + print('timed out while waiting') def wait(millis): global loop + before = GLib.get_monotonic_time() loop = GLib.MainLoop() GLib.timeout_add(millis, quit_cb, loop) loop.run() + if verbose: + time = (GLib.get_monotonic_time() - before) / 1000 + print(f'waited for {time} milliseconds') def monitors_changed(monitors, position, removed, added): global expected_change - assert expected_change != None, "No change expected" - assert position == expected_change['position'], "Unexpected position in monitors-changed" - assert removed == expected_change['removed'], "Unexpected removed in monitors-changed" - assert added == expected_change['added'], "Unexpected added in monitors-changed" + assert expected_change != None, 'No change expected' + assert position == expected_change['position'], 'Unexpected position in monitors-changed' + assert removed == expected_change['removed'], 'Unexpected removed in monitors-changed' + assert added == expected_change['added'], 'Unexpected added in monitors-changed' if verbose: - print('got expected change') + print('got expected monitors-changed signal') expected_change = None loop.quit() @@ -110,7 +118,7 @@ def launch_observer(): print('launch observer') monitor_model = display.get_monitors() - assert monitor_model.get_n_items() == 0, "Unexpected initial monitors" + assert monitor_model.get_n_items() == 0, 'Unexpected initial monitors' monitor_model.connect('items-changed', monitors_changed) def expect_monitors_changed(position, removed, added, timeout): @@ -121,7 +129,7 @@ def expect_monitors_changed(position, removed, added, timeout): 'added' : added } wait(timeout) - assert expected_change == None, "Expected change did not happen" + assert expected_change == None, 'Expected change did not happen' def got_connector(monitor, pspec): loop.quit() @@ -130,15 +138,18 @@ def expect_monitor(position, width, height, scale, freq): assert monitor_model.get_n_items() > position, f'Monitor {position} not present' monitor = monitor_model.get_item(position) if monitor.get_connector() == None: + if verbose: + print('waiting for connector') handler = monitor.connect('notify::connector', got_connector) wait(500) monitor.disconnect(handler) - assert monitor.is_valid(), "Monitor is not valid" + assert monitor.get_connector() != None, 'Monitor has no connector' + assert monitor.is_valid(), 'Monitor is not valid' geometry = monitor.get_geometry() - assert geometry.width == width, "Unexpected monitor width" - assert geometry.height == height, "Unexpected monitor height" - assert monitor.get_scale_factor() == scale, "Unexpected scale factor" - assert monitor.get_refresh_rate() == freq, "Unexpected monitor frequency" + assert geometry.width == width, 'Unexpected monitor width' + assert geometry.height == height, 'Unexpected monitor height' + assert monitor.get_scale_factor() == scale, 'Unexpected scale factor' + assert monitor.get_refresh_rate() == freq, 'Unexpected monitor frequency' if verbose: print(f'monitor {position}: {geometry.width}x{geometry.height} frequency {monitor.get_refresh_rate()} scale {monitor.get_scale_factor()} model \'{monitor.get_model()}\' connector \'{monitor.get_connector()}\'') @@ -146,41 +157,41 @@ def run_commands(): try: launch_observer() - add_monitor("0", width=100, height=100, scale=1, freq=60) - expect_monitors_changed(0, 0, 1, 5000) + add_monitor('0', width=100, height=100, scale=1, freq=60) + expect_monitors_changed(0, 0, 1, 10000) expect_monitor (position=0, width=100, height=100, scale=1, freq=60000) - add_monitor("1", width=1024, height=768, scale=1, freq=144) - expect_monitors_changed(1, 0, 1, 5000) + add_monitor('1', width=1024, height=768, scale=1, freq=144) + expect_monitors_changed(1, 0, 1, 10000) expect_monitor (position=1, width=1024, height=768, scale=1, freq=144000) - remove_monitor("0") + remove_monitor('0') expect_monitors_changed(0, 1, 0, 11000) # mutter takes 10 seconds to remove it - remove_monitor("1") + remove_monitor('1') expect_monitors_changed(0, 1, 0, 11000) except AssertionError as e: - print("Error: {0}".format(e)) + print(f'Error: {e}') terminate() def mutter_appeared(name): global screen_cast global done if verbose: - print("mutter appeared on the bus") + print('mutter appeared on the bus') screen_cast = bus.get('org.gnome.Mutter.ScreenCast', '/org/gnome/Mutter/ScreenCast') run_commands() if verbose: - print ("Done running commands, exiting...") + print ('Done running commands, exiting...') done = True def mutter_vanished(): global done if screen_cast != None: if verbose: - print("mutter left the bus") + print('mutter left the bus') done = True bus = SessionBus() diff --git a/testsuite/headless/meson.build b/testsuite/headless/meson.build index 1f773ed7c4..21aaa10f45 100644 --- a/testsuite/headless/meson.build +++ b/testsuite/headless/meson.build @@ -5,6 +5,7 @@ env.prepend('GI_TYPELIB_PATH', ) env.prepend('LD_PRELOAD', project_build_root / 'gtk' / 'libgtk-4.so') env.prepend('MESON_CURRENT_SOURCE_DIR', meson.current_source_dir()) +env.prepend('MESON_CURRENT_BUILD_DIR', meson.current_build_dir()) test('monitor', find_program('run-headless-monitor-tests.sh', dirs: meson.current_source_dir()), diff --git a/testsuite/headless/run-headless-input-tests.sh b/testsuite/headless/run-headless-input-tests.sh index 53dfeea222..341caa9dca 100755 --- a/testsuite/headless/run-headless-input-tests.sh +++ b/testsuite/headless/run-headless-input-tests.sh @@ -1,26 +1,35 @@ #! /bin/sh srcdir=${MESON_CURRENT_SOURCE_DIR:-./testsuite/headless} +builddir=${MESON_CURRENT_BUILD_DIR:-.} +outputdir=${builddir}/input -dbus-run-session sh <${outputdir}/dbus-stderr.log <&${outputdir}/pipewire.log & pipewire_pid=\$! -wireplumber & +sleep 2 + +wireplumber >&${outputdir}/wireplumber.log & wireplumber_pid=\$! -sleep 1 +sleep 2 #echo DBUS_SESSION_BUS_ADDRESS=\$DBUS_SESSION_BUS_ADDRESS #echo WAYLAND_DISPLAY=gtk-test -export GTK_A11Y=none -export GIO_USE_VFS=local - -mutter --headless --virtual-monitor 1024x768 --no-x11 --wayland-display gtk-test2 >&mutter2.log & +mutter --headless --virtual-monitor 1024x768 --no-x11 --wayland-display gtk-test2 >&${outputdir}/mutter.log & mutter_pid=\$! +sleep 2 + export WAYLAND_DISPLAY=gtk-test2 export GDK_BACKEND=wayland diff --git a/testsuite/headless/run-headless-monitor-tests.sh b/testsuite/headless/run-headless-monitor-tests.sh index 3c36657898..26fd4d0379 100755 --- a/testsuite/headless/run-headless-monitor-tests.sh +++ b/testsuite/headless/run-headless-monitor-tests.sh @@ -1,19 +1,24 @@ #! /bin/sh srcdir=${MESON_CURRENT_SOURCE_DIR:-./testsuite/headless} +builddir=${MESON_CURRENT_BUILD_DIR:-.} +outputdir=${builddir}/monitor + +mkdir -p ${outputdir} + export GTK_A11Y=none export GIO_USE_VFS=local -dbus-run-session sh <${outputdir}/dbus-stderr.log <&${outputdir}/pipewire.log & pipewire_pid=\$! sleep 2 -wireplumber & +wireplumber >&${outputdir}/wireplumber.log & wireplumber_pid=\$! sleep 2 @@ -22,7 +27,7 @@ sleep 2 export MUTTER_DEBUG=screen-cast -mutter --headless --no-x11 --wayland-display gtk-test & +mutter --headless --no-x11 --wayland-display gtk-test >&${outputdir}/mutter.log & mutter_pid=\$! sleep 2