ci: Improve headless test logging

.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"

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 != None, 'Unexpected key press'
-    assert expected_change['type'] == 'press', "Key press event expected"
+    assert expected_change['type'] == 'press', 'Key press event expected'
-    assert keyval == expected_change['keyval'], "Unexpected keyval in key press event"
+    assert keyval == expected_change['keyval'], 'Unexpected keyval in key press event'
-    assert state == expected_change['state'], "Unexpected state 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 != None, 'Unexpected key release'
-    assert expected_change['type'] == 'release', "Key release event expected"
+    assert expected_change['type'] == 'release', 'Key release event expected'
-    assert keyval == expected_change['keyval'], "Unexpected keyval in key release event"
+    assert keyval == expected_change['keyval'], 'Unexpected keyval in key release event'
-    assert state == expected_change['state'], "Unexpected state 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 expected_change['type'] == 'motion', 'Motion event expected'
-        assert x == expected_change['x'], "Unexpected x coord in motion event"
+        assert x == expected_change['x'], 'Unexpected x coord in motion event'
-        assert y == expected_change['y'], "Unexpected y 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 != None, 'Unexpected enter'
-    assert expected_change['type'] == 'enter', "Enter event expected"
+    assert expected_change['type'] == 'enter', 'Enter event expected'
-    assert x == expected_change['x'], "Unexpected x coord in enter event"
+    assert x == expected_change['x'], 'Unexpected x coord in enter event'
-    assert y == expected_change['y'], "Unexpected y 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 != None, 'Unexpected event'
-    assert expected_change['type'] == 'press', "Button press expected"
+    assert expected_change['type'] == 'press', 'Button press expected'
-    assert expected_change['button'] == controller.get_current_button(), "Unexpected button pressed"
+    assert expected_change['button'] == controller.get_current_button(), 'Unexpected button pressed'
-    assert x == expected_change['x'], "Unexpected x coord in motion event"
+    assert x == expected_change['x'], 'Unexpected x coord in motion event'
-    assert y == expected_change['y'], "Unexpected y 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 != None, 'Unexpected event'
-    assert expected_change['type'] == 'release', "Button release expected"
+    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.is_active(), 'Observer not active'
-    assert window.get_width() == 1024, "Window not maximized"
+    assert window.get_width() == 1024, 'Window not maximized'
-    assert window.get_height() == 768, "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')
+        print('got drag begin')
-    assert expected_change != None, "Unexpected drag begin"
+    assert expected_change != None, 'Unexpected drag begin'
-    assert expected_change['type'] == 'drag', "Drag begin expected"
+    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.is_active(), 'drag source not active'
-    assert ds_window.get_width() == 1024, "Window not maximized"
+    assert ds_window.get_width() == 1024, 'Window not maximized'
-    assert ds_window.get_height() == 768, "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 != None, 'Unexpected drop begin'
-    assert expected_change['type'] == 'drop', "Drop expected"
+    assert expected_change['type'] == 'drop', 'Drop expected'
-    assert expected_change['value'] == value, "Unexpected value dropped"
+    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.is_active(), 'drop target not active'
-    assert dt_window.get_width() == 1024, "Window not maximized"
+    assert dt_window.get_width() == 1024, 'Window not maximized'
-    assert dt_window.get_height() == 768, "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 & 1 == 1, 'No keyboard'
-    assert device_types & 2 == 2, "No pointer"
+    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()
+    run_commands()
-    basic_pointer_tests()
-    dnd_tests()
 
     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()

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,
+        'session': session,
-        "width": width,
+        'width': width,
-        "height": height,
+        'height': height,
-        "scale": scale,
+        'scale': scale,
-        "freq": freq
+        '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 expected_change != None, 'No change expected'
-    assert position == expected_change['position'], "Unexpected position in monitors-changed"
+    assert position == expected_change['position'], 'Unexpected position in monitors-changed'
-    assert removed == expected_change['removed'], "Unexpected removed in monitors-changed"
+    assert removed == expected_change['removed'], 'Unexpected removed in monitors-changed'
-    assert added == expected_change['added'], "Unexpected added 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.width == width, 'Unexpected monitor width'
-    assert geometry.height == height, "Unexpected monitor height"
+    assert geometry.height == height, 'Unexpected monitor height'
-    assert monitor.get_scale_factor() == scale, "Unexpected scale factor"
+    assert monitor.get_scale_factor() == scale, 'Unexpected scale factor'
-    assert monitor.get_refresh_rate() == freq, "Unexpected monitor frequency"
+    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)
+        add_monitor('0', width=100, height=100, scale=1, freq=60)
-        expect_monitors_changed(0, 0, 1, 5000)
+        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)
+        add_monitor('1', width=1024, height=768, scale=1, freq=144)
-        expect_monitors_changed(1, 0, 1, 5000)
+        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()

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()),

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 <<EOF
+mkdir -p ${outputdir}
 
-export XDG_RUNTIME_DIR="$(mktemp -p $(pwd) -d xdg-runtime-XXXXXX)"
-
-pipewire &
-pipewire_pid=\$!
-wireplumber &
-wireplumber_pid=\$!
-sleep 1
-
-#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 &
+dbus-run-session sh 2>${outputdir}/dbus-stderr.log <<EOF
+
+export XDG_RUNTIME_DIR="$(mktemp -p $(pwd) -d xdg-runtime-XXXXXX)"
+
+pipewire >&${outputdir}/pipewire.log &
+pipewire_pid=\$!
+sleep 2
+
+wireplumber >&${outputdir}/wireplumber.log &
+wireplumber_pid=\$!
+sleep 2
+
+#echo DBUS_SESSION_BUS_ADDRESS=\$DBUS_SESSION_BUS_ADDRESS
+#echo WAYLAND_DISPLAY=gtk-test
+
+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
 

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 <<EOF
+dbus-run-session sh 2>${outputdir}/dbus-stderr.log <<EOF
 
 export XDG_RUNTIME_DIR="$(mktemp -p $(pwd) -d xdg-runtime-XXXXXX)"
 
-pipewire &
+pipewire >&${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