tieto/sipe

Assert in candidate_pairs_established_cb() when initiating appshare

Closed this issue · 14 comments

@joakim-tjernlund wrote:

So tried to share again an got this error sevral times:

MESSAGE END >>>>>>>>>> SIP - 2016-09-16T14:39:49.393716Z
(16:39:49) sipe: process_input_message: removing CSeq 2
(16:39:49) sipe: SIP transactions count:0 after removal
(16:39:49) backend-fs2: farstream-component-state-changed: component: 1 state: CONNECTING
(16:39:49) backend-fs2: farstream-component-state-changed: component: 2 state: CONNECTING
(16:39:49) sipe: sipe_schedule_remove: action name=<9826gF660aE774iB5F4m4DD3tC057bC674x0E3Ex>
[16:39:49:670] [1182:1182] [INFO][com.freerdp.server.shadow.x11] - X11 Extensions: XFixes: 1 Xinerama: 1 XDamage: 0 XShm: 0
[16:39:49:675] [1182:1182] [INFO][com.freerdp.core.listener] - Listening on 0.0.0.0:3389
**
ERROR:sipe-appshare.c:682:candidate_pairs_established_cb: assertion failed (error == NULL): No such file or directory (g-io-error-quark, 1)
Aborted

This is with upstream freerdp though

and lanchpad too.

The freerdp that works is Gentoo's older snapshot: freerdp-2.0.0_pre20160722
from mid July.

The piece of code pertaining to this issue

    appshare->server = server;
    appshare->socket = g_socket_new(G_SOCKET_FAMILY_UNIX,
                    G_SOCKET_TYPE_STREAM,
                    G_SOCKET_PROTOCOL_DEFAULT,
                    &error);
    g_assert_no_error(error);
    g_socket_set_blocking(appshare->socket, FALSE);

    address = g_unix_socket_address_new(socket_path);
    sleep(3);
    g_socket_connect(appshare->socket, address, NULL, &error);
    g_assert_no_error(error); # HERE IT ASSERTS

I just noticed that I had pidgin open on another computer too with a chat open to the same
person I tested DE sharing.
Maybe it caused some interference?

@joakim-tjernlund Please fetch & build the latest launchpad of sipe repo, try to reproduce the assert again and post new log snippet. Let's see what value socket_path has.

I just noticed that I had pidgin open on another computer too with a chat open to the same person I tested DE sharing. Maybe it caused some interference?

I doubt the second pidgin instance is causing this. Rather something fishy is coming out of build_socket_path().

Just did and no Assert when I start to share.
My co-worker has gone for the day now so I will have to wait until Monday
for him to accept the share and see if it Asserts then.

Maybe it was some socket resource limit on my computer was depleted?
I have a lot running on my computer.

I'm deducing from the error message g_socket_connect() returns:

No such file or directory

Sipe wants to create a unix socket at /run/user/[userid]/sipe/applicationsharing-[pid]-[streamid] through which FreeRDP in turn communicates. I suspect some directory in that path doesn't exist and thus g_socket_connect() can't make the socket special file at the location.

Btw. what's the value of XDG_RUNTIME_DIR environment variable on your machine?

env | grep XDG_RUNTIME
XDG_RUNTIME_DIR=/var/run/user/1001
jocke@gentoo-jocke tieto_sipe.git $ ls -l /var/run/user/1001
total 0
drwx------ 5 jocke root 100 Sep 16 17:50 ./
drwxr-xr-x 3 root root 60 Sep 12 13:21 ../
drwx------ 2 jocke users 60 Sep 16 18:28 dconf/
drwx------ 2 jocke users 80 Sep 12 13:21 pulse/
drwx------ 4 jocke users 100 Sep 16 16:57 sipe/

This looks okay. Let's see what you'll get when you test with your colleague then.

He was sick yesterday but today we tried again and now we cannot repeat the error :(

Then I suggest you keep pidgin running with debug log enabled for a while should the error happen again.

So I got it again:

(10:39:44) sipe: sipe_purple_buddy_share_application_cb: name 'sip:testuser2.metro@infinera.com'
(10:39:47) sipe: sipe_session_add_call: new session for sip:testuser2.metro@infinera.com
(10:39:47) mediamanager: Couldn't read fs-element.conf: No such file or directory
(10:39:47) g_log: gst_ffmpeg_cfg_set_property: assertion 'qdata->size == sizeof (gint64)' failed
(10:39:47) backend-fs2: Creating hash table for sessions
(10:39:47) backend-fs2: connecting pad: success
(10:39:47) backend-fs2: create_src: setting source state to GST_STATE_PLAYING - it may hang here on win32
(10:39:47) backend-fs2: create_src: state set
(10:39:47) backend-fs2: Creating hash table for participants
(10:39:47) GLib-GObject: g_object_newv: object class 'FsNiceStreamTransmitter' has no property named 'discovery-timeout'
(10:39:47) GLib-GObject: unable to set property 'relay-info' of type 'GPtrArray' from value of type 'GValueArray'
(10:39:47) media: Creating hash table for sessions
(10:39:47) sipe: sipe_media_state_changed_cb: 0 applicationsharing (null)

(10:39:47) sipe: sipe_media_state_changed_cb: 0 (null) sip:testuser2.metro@infinera.com

(10:39:47) sipe: sipe_media_state_changed_cb: 0 applicationsharing sip:testuser2.metro@infinera.com

(10:39:47) sipe: sipe_schedule_allocate timeouts count 10 after addition
(10:39:47) sipe: scheduling action <media-stream-connect><47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax><applicationsharing> timeout 30 seconds
(10:39:47) sipe: stream_writable_cb: applicationsharing has become not writable
(10:39:47) backend-fs2: got new local candidate: 4
(10:39:47) backend-fs2: got new local candidate: 3
(10:39:47) backend-fs2: got new local candidate: 4
(10:39:47) backend-fs2: got new local candidate: 3
(10:39:47) backend-fs2: got new local candidate: 1
(10:39:47) backend-fs2: got new local candidate: 2
(10:39:47) backend-fs2: got new local candidate: 1
(10:39:47) backend-fs2: got new local candidate: 2
(10:39:47) sipe: SIP transactions count:1 after addition
(10:39:47) sipe: 
MESSAGE START >>>>>>>>>> SIP - 2016-10-04T08:39:47.301166Z
INVITE sip:testuser2.metro@infinera.com SIP/2.0
Via: SIP/2.0/tls 172.20.4.10:52136
From: <sip:Joakim.Tjernlund@infinera.com>;tag=5257856552;epid=9cc2b36e1337
To: <sip:testuser2.metro@infinera.com>
Max-Forwards: 70
CSeq: 1 INVITE
User-Agent: Purple/2.11.0 Sipe/1.21.1 (linux-x86_64; RTC/6.0)
Call-ID: 47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax
ms-keep-alive: UAC;hop-hop=yes
Contact: <sip:Joakim.Tjernlund@infinera.com;opaque=user:epid:6f3NfyZPcF-QmcquC9evFQAA;gruu>
Content-Type: application/sdp
Content-Length: 724
Authorization: TLS-DSK qop="auth", opaque="B27349C5", realm="SIP Communications Service", targetname="sv-sfbfe-prd1.infinera.com", crand="7dc41548", cnum="19", response="5C7D6600BA265F6E51D8C131570BD9002A1DE36D"

v=0
o=- 0 0 IN IP4 172.20.4.10
s=session
c=IN IP4 172.20.4.10
b=CT:99980
t=0 0
m=applicationsharing 42010 TCP/RTP/AVP 127
a=candidate:3 1 TCP-ACT 2020213247 172.20.4.10 42010 typ host 
a=candidate:3 2 TCP-ACT 2020213247 172.20.4.10 42010 typ host 
a=candidate:4 1 TCP-PASS 2019820031 172.20.4.10 42010 typ host 
a=candidate:4 2 TCP-PASS 2019820031 172.20.4.10 42010 typ host 
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:VAWLGX1A2wPojBrQVr+ATDItKwdZL5IX9qSEkLiz|2^31
a=rtpmap:127 X-DATA/90000
a=rtcp:42010
a=mid:1
a=x-applicationsharing-session-id:1
a=x-applicationsharing-role:sharer
a=x-applicationsharing-media-type:rdp
a=setup:active
a=connection:new
a=ice-ufrag:e66z
a=ice-pwd:IkbLhKd2i33d+XgcCSSsAQ

MESSAGE END >>>>>>>>>> SIP - 2016-10-04T08:39:47.301166Z
(10:39:47) sipe: 
MESSAGE START <<<<<<<<<< SIP - 2016-10-04T08:39:47.484349Z
SIP/2.0 100 Trying
Authentication-Info: TLS-DSK qop="auth", opaque="B27349C5", srand="6FB9FD13", snum="23", rspauth="eb7b8105bad6fc30f14141b01cf465553c328169", targetname="sv-sfbfe-prd1.infinera.com", realm="SIP Communications Service", version=4
From: <sip:Joakim.Tjernlund@infinera.com>;tag=5257856552;epid=9cc2b36e1337
To: <sip:testuser2.metro@infinera.com>
Call-ID: 47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax
CSeq: 1 INVITE
Via: SIP/2.0/tls 172.20.4.10:52136;ms-received-port=52136;ms-received-cid=3FDB00
Server: http%3A%2F%2Fwww.microsoft.com%2FLCS%2FUdcAgent
Content-Length: 0


MESSAGE END <<<<<<<<<< SIP - 2016-10-04T08:39:47.484349Z
(10:39:47) sipe: sip_sec_verify_signature: message is:<TLS-DSK><6FB9FD13><23><SIP Communications Service><sv-sfbfe-prd1.infinera.com><47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax><1><INVITE><sip:Joakim.Tjernlund@infinera.com><5257856552><sip:testuser2.metro@infinera.com><><><><><100> signature to verify is:eb7b8105bad6fc30f14141b01cf465553c328169
(10:39:47) sipe: sip_transport_input: signature of incoming message validated
(10:39:47) sipe: process_input_message: msg->response(100),msg->method(INVITE)
(10:39:47) sipe: process_input_message: got provisional (100) response, ignoring
(10:39:47) sipe: 
MESSAGE START <<<<<<<<<< SIP - 2016-10-04T08:39:47.696945Z
SIP/2.0 101 Progress Report
Authentication-Info: TLS-DSK qop="auth", opaque="B27349C5", srand="AFE030D0", snum="24", rspauth="2c8856303fa5ed2a1f00215690c21492378ffa48", targetname="sv-sfbfe-prd1.infinera.com", realm="SIP Communications Service", version=4
Content-Length: 0
Via: SIP/2.0/tls 172.20.4.10:52136;ms-received-port=52136;ms-received-cid=3FDB00
From: "Joakim Tjernlund"<sip:Joakim.Tjernlund@infinera.com>;tag=5257856552;epid=9cc2b36e1337
To: <sip:testuser2.metro@infinera.com>
Call-ID: 47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax
CSeq: 1 INVITE
ms-diagnostics: 13004;reason="Request was proxied to one or more registered endpoints";source="SV-SFBFE-PRD3.INFINERA.COM";Count="1";appName="InboundRouting"
Server: InboundRouting/6.0.0.0


MESSAGE END <<<<<<<<<< SIP - 2016-10-04T08:39:47.696945Z
(10:39:47) sipe: sip_sec_verify_signature: message is:<TLS-DSK><AFE030D0><24><SIP Communications Service><sv-sfbfe-prd1.infinera.com><47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax><1><INVITE><sip:Joakim.Tjernlund@infinera.com><5257856552><sip:testuser2.metro@infinera.com><><><><><101> signature to verify is:2c8856303fa5ed2a1f00215690c21492378ffa48
(10:39:47) sipe: sip_transport_input: signature of incoming message validated
(10:39:47) sipe: process_input_message: msg->response(101),msg->method(INVITE)
(10:39:47) sipe: process_input_message: got provisional (101) response, ignoring
(10:39:47) sipe: 
MESSAGE START <<<<<<<<<< SIP - 2016-10-04T08:39:47.697248Z
SIP/2.0 180 Ringing
Authentication-Info: TLS-DSK qop="auth", opaque="B27349C5", srand="87E80D78", snum="25", rspauth="e4a3846a78afe09551f79457b9df56095effb08c", targetname="sv-sfbfe-prd1.infinera.com", realm="SIP Communications Service", version=4
Record-Route: <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd3.infinera.com;opaque=state:T;lr>
Via: SIP/2.0/tls 172.20.4.10:52136;ms-received-port=52136;ms-received-cid=3FDB00
Record-Route: <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd1.infinera.com;opaque=state:F:Eu:Ci.R3fdb00;lr;ms-route-sig=bbWJfvqgCL-sKmMhVQ0YRZNY5MUyiXW2Dc0iYf0Bv15y-pUkeiPFEY8QAA>
From: "Joakim Tjernlund"<sip:Joakim.Tjernlund@infinera.com>;tag=5257856552;epid=9cc2b36e1337
CSeq: 1 INVITE
Call-ID: 47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax
To: <sip:testuser2.metro@infinera.com>;epid=0a30fbf02f8c;tag=3444863972
Contact: <sip:testuser2.metro@infinera.com;opaque=user:epid:KrLxp64Y-VOyIxuI_nv6gQAA;gruu>
Content-Length: 0
User-Agent: Purple/2.11.0 Sipe/1.21.1 (linux-x86_64; RTC/6.0)


MESSAGE END <<<<<<<<<< SIP - 2016-10-04T08:39:47.697248Z
(10:39:47) sipe: sip_sec_verify_signature: message is:<TLS-DSK><87E80D78><25><SIP Communications Service><sv-sfbfe-prd1.infinera.com><47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax><1><INVITE><sip:Joakim.Tjernlund@infinera.com><5257856552><sip:testuser2.metro@infinera.com><3444863972><><><><180> signature to verify is:e4a3846a78afe09551f79457b9df56095effb08c
(10:39:47) sipe: sip_transport_input: signature of incoming message validated
(10:39:47) sipe: process_input_message: msg->response(180),msg->method(INVITE)
(10:39:47) sipe: process_input_message: got provisional (180) response, ignoring






(10:39:56) sipe: 
MESSAGE START <<<<<<<<<< SIP - 2016-10-04T08:39:56.523750Z
SIP/2.0 200 OK
Authentication-Info: TLS-DSK qop="auth", opaque="B27349C5", srand="672F06C0", snum="26", rspauth="4bcb69b624f6a8b3bcd52c046292acefefb52731", targetname="sv-sfbfe-prd1.infinera.com", realm="SIP Communications Service", version=4
Via: SIP/2.0/tls 172.20.4.10:52136;ms-received-port=52136;ms-received-cid=3FDB00
Content-Length: 964
Record-Route: <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd3.infinera.com;opaque=state:T;lr>
Record-Route: <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd1.infinera.com;opaque=state:F:Eu:Ci.R3fdb00;lr;ms-route-sig=bbWJfvqgCL-sKmMhVQ0YRZNY5MUyiXW2Dc0iYf0Bv15y-pUkeiPFEY8QAA>
From: "Joakim Tjernlund"<sip:Joakim.Tjernlund@infinera.com>;tag=5257856552;epid=9cc2b36e1337
CSeq: 1 INVITE
Call-ID: 47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax
To: <sip:testuser2.metro@infinera.com>;epid=0a30fbf02f8c;tag=3444863972
Content-Type: application/sdp
Contact: <sip:testuser2.metro@infinera.com;opaque=user:epid:KrLxp64Y-VOyIxuI_nv6gQAA;gruu>
User-Agent: Purple/2.11.0 Sipe/1.21.1 (linux-x86_64; RTC/6.0)

v=0
o=- 0 0 IN IP4 192.168.122.1
s=session
c=IN IP4 192.168.122.1
b=CT:99980
t=0 0
m=applicationsharing 42002 TCP/RTP/SAVP 127
a=candidate:3 1 TCP-ACT 2020212991 192.168.122.1 42002 typ host 
a=candidate:3 2 TCP-ACT 2020212991 192.168.122.1 42002 typ host 
a=candidate:4 1 TCP-PASS 2019819775 192.168.122.1 42002 typ host 
a=candidate:4 2 TCP-PASS 2019819775 192.168.122.1 42002 typ host 
a=candidate:5 1 TCP-ACT 2020212991 192.168.100.48 42000 typ host 
a=candidate:5 2 TCP-ACT 2020212991 192.168.100.48 42000 typ host 
a=candidate:7 1 TCP-PASS 2019819775 192.168.100.48 42000 typ host 
a=candidate:7 2 TCP-PASS 2019819775 192.168.100.48 42000 typ host 
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:RD2VOCt/7xZ3q0lJElPBVgi5eSjdDSaMvF6FpUVp|2^31
a=rtpmap:127 X-DATA/90000
a=rtcp:42002
a=x-applicationsharing-session-id:1
a=x-applicationsharing-role:viewer
a=x-applicationsharing-media-type:rdp
a=ice-ufrag:T+jw
a=ice-pwd:CZ594p6bFzUc4vdiS76hFu

MESSAGE END <<<<<<<<<< SIP - 2016-10-04T08:39:56.523750Z
(10:39:56) sipe: sip_sec_verify_signature: message is:<TLS-DSK><672F06C0><26><SIP Communications Service><sv-sfbfe-prd1.infinera.com><47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax><1><INVITE><sip:Joakim.Tjernlund@infinera.com><5257856552><sip:testuser2.metro@infinera.com><3444863972><><><><200> signature to verify is:4bcb69b624f6a8b3bcd52c046292acefefb52731
(10:39:56) sipe: sip_transport_input: signature of incoming message validated
(10:39:56) sipe: process_input_message: msg->response(200),msg->method(INVITE)
(10:39:56) sipe: process_input_message: we have a transaction callback
(10:39:56) sipe: sipe_dialog_parse_routes: route <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd3.infinera.com;opaque=state:T;lr>
(10:39:56) sipe: sipe_dialog_parse_routes: route <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd1.infinera.com;opaque=state:F:Eu:Ci.R3fdb00;lr;ms-route-sig=bbWJfvqgCL-sKmMhVQ0YRZNY5MUyiXW2Dc0iYf0Bv15y-pUkeiPFEY8QAA>
(10:39:56) sipe: 
MESSAGE START >>>>>>>>>> SIP - 2016-10-04T08:39:56.525532Z
ACK sip:testuser2.metro@infinera.com;opaque=user:epid:KrLxp64Y-VOyIxuI_nv6gQAA;gruu SIP/2.0
Via: SIP/2.0/tls 172.20.4.10:52136
From: <sip:Joakim.Tjernlund@infinera.com>;tag=5257856552;epid=9cc2b36e1337
To: <sip:testuser2.metro@infinera.com>;tag=3444863972;epid=0a30fbf02f8c
Max-Forwards: 70
CSeq: 1 ACK
User-Agent: Purple/2.11.0 Sipe/1.21.1 (linux-x86_64; RTC/6.0)
Call-ID: 47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax
Route: <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd1.infinera.com;opaque=state:F:Eu:Ci.R3fdb00;lr;ms-route-sig=bbWJfvqgCL-sKmMhVQ0YRZNY5MUyiXW2Dc0iYf0Bv15y-pUkeiPFEY8QAA>
Route: <sip:SFBPool.infinera.com:5061;transport=tls;ms-fe=sv-sfbfe-prd3.infinera.com;opaque=state:T;lr>
Content-Length: 0
Authorization: TLS-DSK qop="auth", opaque="B27349C5", realm="SIP Communications Service", targetname="sv-sfbfe-prd1.infinera.com", crand="7a2bc0f4", cnum="20", response="453EE9D2D19C6C858AB22A5450689EA061B03418"


MESSAGE END >>>>>>>>>> SIP - 2016-10-04T08:39:56.525532Z
(10:39:56) sipe: process_input_message: removing CSeq 6
(10:39:56) sipe: SIP transactions count:0 after removal
(10:39:56) backend-fs2: farstream-component-state-changed: component: 1 state: CONNECTING
(10:39:56) backend-fs2: farstream-component-state-changed: component: 2 state: CONNECTING
(10:39:56) sipe: sipe_schedule_remove: action name=<media-stream-connect><47DFg8602a7978i3DD9mFAD4tA6A8bE6BDx960Ax><applicationsharing>
[10:39:56:065] [19991:19991] [INFO][com.freerdp.server.shadow.x11] - X11 Extensions: XFixes: 1 Xinerama: 1 XDamage: 0 XShm: 0
[10:39:56:071] [19991:19991] [INFO][com.freerdp.core.listener] - Listening on 0.0.0.0:3389
(10:39:56) sipe: Appshare socket path is: /var/run/user/1001/sipe/applicationsharing-19991-0x1863000
**
ERROR:sipe-appshare.c:684:candidate_pairs_established_cb: assertion failed (error == NULL): No such file or directory (g-io-error-quark, 1)

ls -l /var/run/user/1001/sipe/
total 0
drwx------ 2 jocke users 40 Oct 4 10:37 ./
drwx------ 6 jocke root 120 Oct 4 09:05 ../

FreeRDP shadow server is responsible for creating the unix socket in /var/run/user/1001/sipe/, but apparently it opens a TCP socket instead:

[10:39:56:071] [19991:19991] [INFO][com.freerdp.core.listener] - Listening on 0.0.0.0:3389

This is strange, though, because the code deciding what kind of socket will be created is in shadow_server_start() as follows:

if (!server->ipcSocket)
    status = server->listener->Open(server->listener, NULL, (UINT16) server->port);
else
    status = server->listener->OpenLocal(server->listener, server->ipcSocket);

Open creates TCP socket, OpenLocal unix socket, and we always set server->ipcSocket to the unix socket path (/var/run/user/...) in Sipe prior calling shadow_server_start():

socket_path = build_socket_path(stream);
server->ipcSocket = g_strdup(socket_path);
server->authentication = FALSE;
server->mayInteract = FALSE;
set_shared_display_area(server, appshare->monitor_id);

if(shadow_server_init(server) < 0) {
    server_error = _("Could not initialize RDP server.");
} else if(shadow_server_start(server) < 0) {
    server_error = _("Could not start RDP server.");
}

We know from your log that socket_path - and thus server->ipcSocket - contains valid non-empty string

(10:39:56) sipe: Appshare socket path is: /var/run/user/1001/sipe/applicationsharing-19991-0x1863000

so I don't understand how possibly could the code in shadow_server_start() evaluate server->ipcSocket as NULL and in turn call Open instead of OpenLocal.

This all looks more like some random memory corruption or mis-compilation of FreeRDP. Could you please try rebuilding it on your system (and Sipe as well just to be sure)? Which FreeRDP version are you using, upstream master?

I am using FreeRDP upstream master and yes this is strange.
I rebuilt freerdp, pidgin and pidgin-sipe and now the error is gone. I have rebuilt this stuff
many times and either I messed up or there is some ABI incompatibility somewhere.
I also noticed I have missed some gstreamer pkgs going form 1.6.3 to 1.8.3 so maybe
something there, who knowns.

AFAIK FreeRDP doesn't maintain any ABI compatibility during development on master branch, so please if you update it, always rebuild pidgin-sipe and remmina for good measure.

I consider this ticket solved. Reopen should the issue arise again.