Source: gnome-remote-desktop Version: 48~alpha-2 Severity: important Tags: ftbfs User: [email protected] Usertags: flaky
There is an intermittent test failure in gnome-remote-desktop, in practice mainly affecting autopkgtest. It could also cause a build-time test failure, but for whatever reason, in practice that has only been observed on s390x. The failure occurs in the "gnome-remote-desktop/rdp" test, and the distinctive error message appears to be "RDP test client exited incorrectly: -11", which I believe indicates that a test client segfaulted. If I'm understanding correctly, this is not the actual gnome-remote-desktop RDP server crashing, but instead it's a crash in a RDP client that was run against it for testing purposes. If a different test failure is observed, please report it separately rather than entangling it with this one. Sample output (from a s390x buildd log, back in March): https://buildd.debian.org/status/fetch.php?pkg=gnome-remote-desktop&arch=s390x&ver=48%7Ealpha-2%2Bb1&stamp=1742129611&raw=0 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.683: [RDP.DRDYNVC] DVC > channel id 3 creation status: -1073741275 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.683: > [RDP.AUDIO_PLAYBACK] Using codec Opus with sample buffer size 3840 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.683: [RDP.DISP] Failed > to open channel (CreationStatus -1073741275). Terminating protocol > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.683: [RDP.DISP] > Tearing down channel > length: 8 > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_finalize_set_flag][0x2aa120c8560]: > [CONNECTION_STATE_FINALIZATION_CLIENT_COOPERATE] received flag > FINALIZE_SC_CONTROL_COOPERATE_PDU [0x00000002] > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_client_transition_to_state][0x2aa120c8560]: > CONNECTION_STATE_FINALIZATION_CLIENT_COOPERATE --> > CONNECTION_STATE_FINALIZATION_CLIENT_GRANTED_CONTROL > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_read_share_control_header][0x2aa120c8560]: > type=PDU_TYPE_DATA[0x00000007], tpktLength=26, remainingLength=20 > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_recv_data_pdu][0x2aa120c8560]: recv Control Data PDU (0x14), length: 8 > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_finalize_set_flag][0x2aa120c8560]: > [CONNECTION_STATE_FINALIZATION_CLIENT_GRANTED_CONTROL] received flag > FINALIZE_SC_CONTROL_GRANTED_PDU [0x00000004] > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_client_transition_to_state][0x2aa120c8560]: > CONNECTION_STATE_FINALIZATION_CLIENT_GRANTED_CONTROL --> > CONNECTION_STATE_FINALIZATION_CLIENT_FONT_MAP > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_read_share_control_header][0x2aa120c8560]: > type=PDU_TYPE_DATA[0x00000007], tpktLength=26, remainingLength=20 > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_recv_data_pdu][0x2aa120c8560]: recv Font Map Data PDU (0x28), length: 8 > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_finalize_set_flag][0x2aa120c8560]: > [CONNECTION_STATE_FINALIZATION_CLIENT_FONT_MAP] received flag > FINALIZE_SC_FONT_MAP_PDU [0x00000008] > [12:53:30:619] [1089:00000441] [DEBUG][com.freerdp.core.rdp] - > [rdp_client_transition_to_state][0x2aa120c8560]: > CONNECTION_STATE_FINALIZATION_CLIENT_FONT_MAP --> CONNECTION_STATE_ACTIVE > [12:53:30:622] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: process_create_request: ChannelId=1 > ChannelName=Microsoft::Windows::RDS::Graphics > [12:53:30:622] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [dvcman_create_channel]: listener Microsoft::Windows::RDS::Graphics created > new channel 1 > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: channel created > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [dvcman_open_channel]: open_channel: ChannelId 1 > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: process_create_request: ChannelId=2 > ChannelName=AUDIO_PLAYBACK_DVC > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [dvcman_create_channel]: listener AUDIO_PLAYBACK_DVC created new channel 2 > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: channel created > [12:53:30:628] [1089:0000044f] [INFO][com.freerdp.channels.rdpsnd.client] - > [rdpsnd_load_device_plugin]: [dynamic] Loaded fake backend for rdpsnd > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [dvcman_open_channel]: open_channel: ChannelId 2 > [12:53:30:628] [1089:0000044e] [DEBUG][com.freerdp.channels.rdpsnd.client] - > [rdpsnd_recv_server_audio_formats_pdu]: [dynamic] Server Audio Formats > [12:53:30:628] [1089:0000044e] [DEBUG][com.freerdp.channels.rdpsnd.client] - > [rdpsnd_send_client_audio_formats]: [dynamic] Client Audio Formats > [12:53:30:628] [1089:0000044e] [DEBUG][com.freerdp.channels.rdpsnd.client] - > [rdpsnd_send_quality_mode_pdu]: [dynamic] QualityMode: 2 > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: process_create_request: ChannelId=3 > ChannelName=Microsoft::Windows::RDS::DisplayControl > [12:53:30:628] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: no listener for > 'Microsoft::Windows::RDS::DisplayControl' > [12:53:30:629] [1089:0000044e] [DEBUG][com.freerdp.channe** > (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.683: [RDP.AUDIO_PLAYBACK] > Received Training Confirm PDU > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.687: [RDP] Layout > manager: Creating PipeWire stream for node id 42 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.687: PipeWire stream > state changed from unconnected to connecting > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.688: [RDP] Layout > manager: Updating state from AWAIT_STREAMS to AWAIT_VIDEO_SIZES > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.688: PipeWire stream > state changed from connecting to paused > libmutter-Message: 12:53:30.692: Added virtual monitor Meta-0 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.696: [RDP] Stream > parameters changed. New surface size: [800, 600] > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.698: [RDP] Layout > manager: Updating state from AWAIT_VIDEO_SIZES to START_RENDERING > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.698: [RDP] Layout > manager: Updating state from START_RENDERING to AWAIT_CONFIG > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.698: [RDP] Layout > manager: Finished applying new monitor config > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.826: PipeWire stream > state changed from paused to streaming > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.827: ei: New region: > mapping-id: 333e2ee2-aea7-46f9-b9ee-77ba2ea40089, 800x600 (0, 0) > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.827: ei: Handled event > type EI_EVENT_DEVICE_ADDED > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.827: ei: Handled event > type EI_EVENT_DEVICE_RESUMED > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.836: [RDP.RDPGFX] > Resetting graphics > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.836: [RDP.RDPGFX] > Creating surface with id 0 > ** Message: 12:53:30.836: New desktop size: [800, 600] > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.842: [RDP.TELEMETRY] > DVC channel id assigned to id 4 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.857: [RDP.DRDYNVC] DVC > channel id 4 creation status: -1073741275 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.857: [RDP.TELEMETRY] > Failed to open channel (CreationStatus -1073741275). Terminating protocol > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.857: [RDP.TELEMETRY] > Tearing down channel > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.858: [RDP] Remote > Desktop session metrics: _post_connect: 127ms, _ready: 1ms, _started: 5ms, > whole startup: 134ms > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.858: [RDP] Surface > 800x600 (0, 0) Metrics: First frame: Reception: 159ms, Transmission: 21ms, > Skipped frames: 0 > ** Message: 12:53:30.868: Region invalidated: [x: 0, y: 0, w: 800, h: 600] > ** Message: 12:53:30.868: Test 1 (Virtual monitor size) was successful! > ls.rdpsnd.client] - [rdpsnd_recv_training_pdu]: [dynamic] Training Request: > wTimeStamp: 0 wPackSize: 1024 > [12:53:30:629] [1089:0000044e] [DEBUG][com.freerdp.channels.rdpsnd.client] - > [rdpsnd_send_training_confirm_pdu]: [dynamic] Training Response: wTimeStamp: > 0 wPackSize: 1024 > [12:53:30:803] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: process_create_request: ChannelId=4 > ChannelName=Microsoft::Windows::RDS::Telemetry > [12:53:30:803] [1089:0000044f] [DEBUG][com.freerdp.channels.drdynvc.client] - > [drdynvc_process_create_request]: no listener for > 'Microsoft::Windows::RDS::Telemetry' > ** (process:1089): DEBUG: 12:53:30.868: Main loop tests complete: 1 > ** Message: 12:53:30.868: Freeing client > [12:53:30:815] [1076:0000044b] [ERROR][com.freerdp.core.transport] - > [transport_read_layer]: BIO_read retries exceeded > [12:53:30:815] [1076:0000044b] [ERROR][com.freerdp.core.peer] - > [transport_read_layer]: ERRCONNECT_CONNECT_TRANSPORT_FAILED [0x0002000D] > ** Message: 12:53:30.869: [RDP] Network or intentional disconnect, stopping > session > [12:53:30:815] [1076:0000044b] [DEBUG][com.freerdp.core.transport] - > [transport_check_fds]: transport_check_fds: transport_read_pdu() - -1 > [12:53:30:815] [1076:0000044b] [DEBUG][com.freerdp.core.rdp] - > [rdp_check_fds][0x2aa1ee6d870]: transport_check_fds() - -1 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.869: RDP client gone > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.869: Stopping RDP > session > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.869: [RDP.RDPGFX] > Deleting surface with id 0 > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.870: PipeWire stream > state changed from streaming to paused > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.870: PipeWire stream > state changed from paused to unconnected > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.874: Stopping stream 0 > [12:53:30:821] [1076:00000434] [ERROR][com.freerdp.core.transport] - > [transport_default_write]: BIO_should_retry returned an error: > error:80000020:system library::Broken pipe > libmutter-Message: 12:53:30.876: Removed virtual monitor Meta-0 > [12:53:30:821] [1076:00000434] [DEBUG][com.freerdp.core] - > [mcs_send_disconnect_provider_ultimatum]: sending > DisconnectProviderUltimatum(rn-provider-initiated) > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.877: RDP session > stopped > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.877: Stream 0 stopped > ** (gnome-remote-desktop-daemon:1076): DEBUG: 12:53:30.882: Received SIGTERM > signal. Exiting... > ** Message: 12:53:30.882: RDP server stopped > Starting mutter > Remote desktop capable display server appeared > Starting RDP server > Running RDP test client > RDP test client exited incorrectly: -11 > Stopping RDP server > Stopping mutter > Waiting for mutter to terminate > Done > + kill -9 1044 1041 > + rm -rf /tmp/g-r-d-tests-Wfo7Y1 > ―――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――― > 1/3 gnome-remote-desktop/rdp FAIL 7.72s exit status 1 Also observed in for example <https://ci.debian.net/packages/g/gnome-remote-desktop/testing/amd64/61429293/>; I would estimate that 5% to 10% of autopkgtest runs fail like this. I do not have any specific knowledge about the internals of gnome-remote-desktop or its test infrastructure. I am aware that some project members consider me to be personally responsible for every test failure in GNOME, and I am sorry that I cannot accept that responsibility. I suspect that a good first thing to try, for anyone interested in investigating this, would be to reproduce it on a developer system by running the tests in a loop, and get a stack trace from systemd-coredump or similar. If it can be reproduced during build-time tests (by doing a single build, then running the equivalent of dh_auto_test repeatedly) then that is probably an easier and more efficient environment for interactive debugging than the autopkgtest would be. smcv
