test_close_stdin times out

[bluca]

On Debian testing, both on my host and in a minimal build container, ninja test fails as test_close_stdin times out:

../tests/test_xnmp.py::TestXnmp::test_close_stdin (process:308): Dex-DEBUG: 19:47:13.564: Using AIO backend DexUringAioBackend
(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.565: Bus org.freedesktop.NativeMessagingProxy acquired
(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.565: Bus name org.freedesktop.NativeMessagingProxy acquired
Handling Start org.example.writeonclose (firefox)
(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): GLib-GIO-DEBUG: 19:47:13.664: _g_io_module_get_default: Found default implementation local (GLocalVfs) for ‘gio-vfs’
(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.665: Found manifest /tmp/xnmp-testroot-2tei6ftm/tmpdir/native-messaging-hosts/org.example.writeonclose.json
(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.665: Spawning native messaging host /srv/build/xdg-native-messaging-proxy-0.1.0/tests/native-messaging-hosts/write-on-close.py

(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.666: registering running messaging host handle: /org/freedesktop/nativemessagingproxy/7235659577232326706
(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.667: native messaging host failed: Child process exited with code 127

(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.667: Emitting Closed signal on :1.0

(/srv/build/xdg-native-messaging-proxy-0.1.0/obj-x86_64-linux-gnu/src/xdg-native-messaging-proxy:308): xdg-native-messaging-proxy-DEBUG: 19:47:13.667: unregistering running messaging host handle: /org/freedesktop/nativemessagingproxy/7235659577232326706
==============================================================================


Summary of Failures:

1/1 xnmp TIMEOUT        120.09s   killed by signal 15 SIGTERM

Does this test require any running service or any other dependency?

[swick]

The tests have no dependencies. Everything that should be required is set up by the conftest.py file. This particular case should check that the fd is closed inside the proxy so that the native messaging host notices the browser closing it. That was fixed in 7963b53.

[bluca]

Strange, this reliably fails on my debian 13 laptop host, and in debian 13 build containers. Built from latest main.

[bluca]

Any more debugs I can enable?

[swick]

I don't see any immediately useful debug options here and suspect that this requires proper debugging. Maybe strace on the service and the test native messaging host might already show the problem.

[bluca]

Ok I'll give it a shot, if you have any more suggestions please share them, otherwise I'll start by stracing

[bluca]

Can't see anything useful in strace, it just keeps polling, waiting for the file to appear.

With XNMP_DBUS_MONITOR=1 this is where it gets stuck:

test_xnmp.py::TestXnmp::test_close_stdin dbus-daemon[1799419]: [session uid=1000 pid=1799419 pidfd=4] Connection :1.1 (uid=1000 pid=1799421 comm="dbus-monitor --session") became a monitor.
signal time=1754948362.109339 sender=org.freedesktop.DBus -> destination=:1.1 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.1"
signal time=1754948362.109351 sender=org.freedesktop.DBus -> destination=:1.1 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.1"
method call time=1754948362.109562 sender=:1.0 -> destination=org.freedesktop.DBus serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameHasOwner
   string "org.freedesktop.NativeMessagingProxy"
method return time=1754948362.109566 sender=org.freedesktop.DBus -> destination=:1.0 serial=3 reply_serial=2
   boolean false
(process:1799422): Dex-DEBUG: 22:39:22.111: Using AIO backend DexUringAioBackend
method call time=1754948362.112611 sender=:1.2 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
method return time=1754948362.112620 sender=org.freedesktop.DBus -> destination=:1.2 serial=1 reply_serial=1
   string ":1.2"
signal time=1754948362.112627 sender=org.freedesktop.DBus -> destination=(null destination) serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.2"
   string ""
   string ":1.2"
signal time=1754948362.112637 sender=org.freedesktop.DBus -> destination=:1.2 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.2"
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.112: Bus org.freedesktop.NativeMessagingProxy acquired
method call time=1754948362.112950 sender=:1.2 -> destination=org.freedesktop.DBus serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus'"
method return time=1754948362.112957 sender=org.freedesktop.DBus -> destination=:1.2 serial=3 reply_serial=2
method call time=1754948362.113009 sender=:1.2 -> destination=org.freedesktop.DBus serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RequestName
   string "org.freedesktop.NativeMessagingProxy"
   uint32 1
signal time=1754948362.113016 sender=org.freedesktop.DBus -> destination=(null destination) serial=6 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.freedesktop.NativeMessagingProxy"
   string ""
   string ":1.2"
signal time=1754948362.113027 sender=org.freedesktop.DBus -> destination=:1.2 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string "org.freedesktop.NativeMessagingProxy"
method return time=1754948362.113034 sender=org.freedesktop.DBus -> destination=:1.2 serial=5 reply_serial=3
   uint32 1
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.113: Bus name org.freedesktop.NativeMessagingProxy acquired
method call time=1754948362.209844 sender=:1.0 -> destination=org.freedesktop.DBus serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameHasOwner
   string "org.freedesktop.NativeMessagingProxy"
method return time=1754948362.209867 sender=org.freedesktop.DBus -> destination=:1.0 serial=4 reply_serial=3
   boolean true
method call time=1754948362.210283 sender=:1.0 -> destination=org.freedesktop.DBus serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=GetNameOwner
   string "org.freedesktop.NativeMessagingProxy"
method return time=1754948362.210290 sender=org.freedesktop.DBus -> destination=:1.0 serial=5 reply_serial=4
   string ":1.2"
method call time=1754948362.210340 sender=:1.0 -> destination=:1.2 serial=5 path=/org/freedesktop/nativemessagingproxy; interface=org.freedesktop.DBus.Introspectable; member=Introspect
method return time=1754948362.210566 sender=:1.2 -> destination=:1.0 serial=4 reply_serial=5
   string "<!DOCTYPE node PUBLIC "-//freedesktop//DTD D-BUS Object Introspection 1.0//EN"
                      "http://www.freedesktop.org/standards/dbus/1.0/introspect.dtd">
<!-- GDBus 2.84.3 -->
<node>
  <interface name="org.freedesktop.DBus.Properties">
    <method name="Get">
      <arg type="s" name="interface_name" direction="in"/>
      <arg type="s" name="property_name" direction="in"/>
      <arg type="v" name="value" direction="out"/>
    </method>
    <method name="GetAll">
      <arg type="s" name="interface_name" direction="in"/>
      <arg type="a{sv}" name="properties" direction="out"/>
    </method>
    <method name="Set">
      <arg type="s" name="interface_name" direction="in"/>
      <arg type="s" name="property_name" direction="in"/>
      <arg type="v" name="value" direction="in"/>
    </method>
    <signal name="PropertiesChanged">
      <arg type="s" name="interface_name"/>
      <arg type="a{sv}" name="changed_properties"/>
      <arg type="as" name="invalidated_properties"/>
    </signal>
  </interface>
  <interface name="org.freedesktop.DBus.Introspectable">
    <method name="Introspect">
      <arg type="s" name="xml_data" direction="out"/>
    </method>
  </interface>
  <interface name="org.freedesktop.DBus.Peer">
    <method name="Ping"/>
    <method name="GetMachineId">
      <arg type="s" name="machine_uuid" direction="out"/>
    </method>
  </interface>
  <interface name="org.freedesktop.NativeMessagingProxy">
    <method name="GetManifest">
      <annotation name="org.qtproject.QtDBus.QtTypeName.In2" value="QVariantMap"/>
      <arg type="s" name="messaging_host_name" direction="in"/>
      <arg type="s" name="mode" direction="in"/>
      <arg type="a{sv}" name="options" direction="in"/>
      <arg type="s" name="manifest" direction="out"/>
    </method>
    <method name="Start">
      <annotation name="org.qtproject.QtDBus.QtTypeName.In2" value="QVariantMap"/>
      <arg type="s" name="messaging_host_name" direction="in"/>
      <arg type="s" name="extension_or_origin" direction="in"/>
      <arg type="s" name="mode" direction="in"/>
      <arg type="a{sv}" name="options" direction="in"/>
      <arg type="h" name="stdin" direction="out"/>
      <arg type="h" name="stdout" direction="out"/>
      <arg type="h" name="stderr" direction="out"/>
      <arg type="o" name="handle" direction="out"/>
    </method>
    <method name="Close">
      <annotation name="org.qtproject.QtDBus.QtTypeName.In1" value="QVariantMap"/>
      <arg type="o" name="handle" direction="in"/>
      <arg type="a{sv}" name="options" direction="in"/>
    </method>
    <signal name="Closed">
      <arg type="o" name="handle"/>
      <arg type="a{sv}" name="options"/>
    </signal>
    <property type="u" name="version" access="read"/>
  </interface>
</node>
"
method call time=1754948362.210780 sender=:1.0 -> destination=:1.2 serial=6 path=/org/freedesktop/nativemessagingproxy; interface=org.freedesktop.NativeMessagingProxy; member=Start
   string "org.example.writeonclose"
   string "some-extension@example.org"
   string "firefox"
   array [
   ]
Handling Start org.example.writeonclose (firefox)
method call time=1754948362.211971 sender=:1.2 -> destination=org.freedesktop.DBus serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0='org.gtk.vfs.Daemon'"
method return time=1754948362.211975 sender=org.freedesktop.DBus -> destination=:1.2 serial=7 reply_serial=5
method call time=1754948362.212013 sender=:1.2 -> destination=org.freedesktop.DBus serial=6 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=StartServiceByName
   string "org.gtk.vfs.Daemon"
   uint32 0
error time=1754948362.212018 sender=org.freedesktop.DBus -> destination=:1.2 error_name=org.freedesktop.DBus.Error.ServiceUnknown reply_serial=6
   string "The name org.gtk.vfs.Daemon was not provided by any .service files"
method call time=1754948362.212085 sender=:1.2 -> destination=org.freedesktop.DBus serial=7 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=GetNameOwner
   string "org.gtk.vfs.Daemon"
error time=1754948362.212088 sender=org.freedesktop.DBus -> destination=:1.2 error_name=org.freedesktop.DBus.Error.NameHasNoOwner reply_serial=7
   string "Could not get owner of name 'org.gtk.vfs.Daemon': no such name"
method call time=1754948362.212151 sender=:1.2 -> destination=org.gtk.vfs.Daemon serial=8 path=/org/gtk/vfs/mounttracker; interface=org.gtk.vfs.MountTracker; member=ListMountableInfo
error time=1754948362.212153 sender=org.freedesktop.DBus -> destination=:1.2 error_name=org.freedesktop.DBus.Error.ServiceUnknown reply_serial=8
   string "The name org.gtk.vfs.Daemon was not provided by any .service files"
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): GVFS-DEBUG: 22:39:22.212: org.gtk.vfs.MountTracker.listMountableInfo call failed: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gtk.vfs.Daemon was not provided by any .service files (g-dbus-error-quark, 2)

method call time=1754948362.212231 sender=:1.2 -> destination=org.freedesktop.DBus serial=9 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): GLib-GIO-DEBUG: 22:39:22.212: _g_io_module_get_default: Found default implementation local (GLocalVfs) for ‘gio-vfs’
   string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0='org.gtk.vfs.Daemon'"
method return time=1754948362.212236 sender=org.freedesktop.DBus -> destination=:1.2 serial=11 reply_serial=9
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.212: Found manifest /tmp/xnmp-testroot-9i269305/tmpdir/native-messaging-hosts/org.example.writeonclose.json
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.212: Spawning native messaging host /home/bluca/git/xdg-native-messaging-proxy/tests/native-messaging-hosts/write-on-close.py

(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.213: registering running messaging host handle: /org/freedesktop/nativemessagingproxy/5889066499991502921
method return time=1754948362.213609 sender=:1.2 -> destination=:1.0 serial=10 reply_serial=6
   file descriptor
         inode: 5956064
         type: fifo
   file descriptor
         inode: 5956065
         type: fifo
   file descriptor
         inode: 5956066
         type: fifo
   object path "/org/freedesktop/nativemessagingproxy/5889066499991502921"
(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.214: native messaging host failed: Child process exited with code 127

(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.214: Emitting Closed signal on :1.0

(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.214: unregistering running messaging host handle: /org/freedesktop/nativemessagingproxy/5889066499991502921
signal time=1754948362.214178 sender=:1.2 -> destination=:1.0 serial=11 path=/org/freedesktop/nativemessagingproxy; interface=org.freedesktop.NativeMessagingProxy; member=Closed
   object path "/org/freedesktop/nativemessagingproxy/5889066499991502921"
   array [
   ]

[swick]

(/home/bluca/git/xdg-native-messaging-proxy/tests/../build/src/xdg-native-messaging-proxy:1799422): xdg-native-messaging-proxy-DEBUG: 22:39:22.214: native messaging host failed: Child process exited with code 127

That should not happen.

For some reason executing write-on-close.py fails which means the fail never gets created.

[bluca]

Right, got it: the problem is #!/usr/bin/env python. On Debian and derivatives there's no python, there's python3

[bluca]

Is it ok to change to env python3? If so, --> #11