Bug#1109043: gnome-remote-desktop: intermittent test failure: RDP test client exited incorrectly: -11

[Simon McVittie]

Source: gnome-remote-desktop
Version: 48~alpha-2
Severity: important
Tags: ftbfs
User: debian-ci at lists.debian.org
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