Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Signaling messages lost in the social provider #739

Closed
iislucas opened this issue Dec 27, 2014 · 9 comments
Closed

Signaling messages lost in the social provider #739

iislucas opened this issue Dec 27, 2014 · 9 comments
Labels
P1
Milestone
v-focus-2015-02-02

Comments

@iislucas
Copy link
Contributor

Version: uProxy from dev ( commit 99cc2d1 , as of Tue Dec 23 11:10:49 2014 -0500 ), tested on Chrome Canary.

Steps:

  1. Startup 2 uproxy instances on difference chrome branches...
  2. A requests access from B
  3. B grants access

Expected:

  • A sees the option to get access.
  • B sees the option to revoke access.

Actually see:

  • A has the cancel request option.
  • B has the option to cancel the offer.

Additional Details:
From looking at the logs, it doesn't look like A ever got B's offer message.

Also, From looing at B, it looks like we may have broken some variable namings... I see this in the logs:

 Core: UI.syncUser {"network":"Google","user":{"userId":"[email protected]","name":"A","imageData":"...","isOnline":true},"instances":[{"instanceId":"abb4d10019ae311e8bf5131c81ed8bb097176e12","description":"","keyHash":"","consent":{"localGrantsAccessToRemote_":true,"localRequestsAccessFromRemote_":false,"remoteGrantsAccessToLocal":false,"remoteRequestsAccessFromLocal":false,"ignoringRemoteUserRequest":false,"ignoringRemoteUserOffer":false,"localGrantsAccessToRemote":true,"localRequestsAccessFromRemote":false},"access":{"asClient":false,"asProxy":false},"isOnline":true,"bytesSent":0,"bytesReceived":0}]}

In particular, notice the suspicious fact that we have both the key localGrantsAccessToRemote_ and the key localGrantsAccessToRemote in the consent state. Also: localRequestsAccessFromRemote_ and localRequestsAccessFromRemote.
@iislucas iislucas added this to the v0.6 Allardice (Web Store Feature Complete) milestone Dec 27, 2014
@salomegeo
Copy link
Collaborator

localGrantsAccessToRemote is a getter for localGrantsAccessToRemote_, i believe.

@salomegeo
Copy link
Collaborator

I can't reproduce this. Did you reload the app or sign out/in while you were doing it?

@dborkan
Copy link
Contributor

dborkan commented Dec 29, 2014

Just tried, also not able to replicate

@iislucas
Copy link
Contributor Author

Hrm... wonder if it was related to having multiple instances online... I'll do more debugging and see how to reproduce it. Thanks for trying.

@iislucas iislucas reopened this Dec 29, 2014
@salomegeo
Copy link
Collaborator

This seems more like xmpp failure and could be related to #725.

@iislucas
Copy link
Contributor Author

w.r.t. localGrantsAccessToRemote and localGrantsAccessToRemote_: in the code sample, they are both boolean params of the UI update message. This is definitely not right. :)

@iislucas
Copy link
Contributor Author

OK, I couldn't reproduce the exact same thing, but what is happening pretty consistently (and looks like it could easily be the same underlying issue) is that some of the messages sent via XMPP do not get to the other side. e.g. exert from end of getter log:

social.js:117 [Google] Running monitor
plumbing.js:45 extension message:  Object
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.251] negotiateConnection()
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.252] socksRtc: openDataChannel: ; options=undefined
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.256] socksRtc: negotiateConnection_
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:3158668251 1 udp 2122260223 192.168.148.75 49747 typ host generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":0,"description":{"type":"offer","sdp":"v=0\r\no=- 508213523960966982 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=msid-semantic: WMS\r\nm=application 9 DTLS/SCTP 5000\r\nc=IN IP4 0.0.0.0\r\na=ice-ufrag:flgjnf/svSPDms38\r\na=ice-pwd:6MS7Y3OvNrxMXQ/Kr9mTGvm8\r\na=ice-options:google-ice\r\na=fingerprint:sha-256 B3:5F:C8:AC:3B:6F:36:EB:8D:4F:BC:6F:ED:51:D8:82:C7:15:6C:B5:70:7D:7B:B5:3F:0F:40:F6:27:DE:7C:95\r\na=setup:actpass\r\na=mid:data\r\na=sctpmap:5000 webrtc-datachannel 1024\r\n"}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 39516 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 36448 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:4073099051 1 tcp 1518280447 192.168.148.75 0 typ host tcptype active generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 33602 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 37255 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 37811 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] sending ------> {"type":3001,"data":{"type":3}}

exert from end of giver log:

[Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:3158668251 1 udp 2122260223 192.168.148.75 49747 typ host generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] received <------ {"type":3001,"data":{"type":0,"description":{"type":"offer","sdp":"v=0\r\no=- 508213523960966982 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=msid-semantic: WMS\r\nm=application 9 DTLS/SCTP 5000\r\nc=IN IP4 0.0.0.0\r\na=ice-ufrag:flgjnf/svSPDms38\r\na=ice-pwd:6MS7Y3OvNrxMXQ/Kr9mTGvm8\r\na=ice-options:google-ice\r\na=fingerprint:sha-256 B3:5F:C8:AC:3B:6F:36:EB:8D:4F:BC:6F:ED:51:D8:82:C7:15:6C:B5:70:7D:7B:B5:3F:0F:40:F6:27:DE:7C:95\r\na=setup:actpass\r\na=mid:data\r\na=sctpmap:5000 webrtc-datachannel 1024\r\n"}}}
scripts/user.js:173 [User Inf Mally] received client{"userId":"[email protected]","clientId":"[email protected]/uproxyB013CA8B","status":1}
scripts/user.js:34 Client already in memory and is unchanged
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.659] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:3158668251 1 udp 2122260223 192.168.148.75 49747 typ host generation 0","sdpMid":"data","sdpMLineIndex":0}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.660] rtcNet: handleSignalMessage: 
{"type":0,"description":{"type":"offer","sdp":"v=0\r\no=- 508213523960966982 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=msid-semantic: WMS\r\nm=application 9 DTLS/SCTP 5000\r\nc=IN IP4 0.0.0.0\r\na=ice-ufrag:flgjnf/svSPDms38\r\na=ice-pwd:6MS7Y3OvNrxMXQ/Kr9mTGvm8\r\na=ice-options:google-ice\r\na=fingerprint:sha-256 B3:5F:C8:AC:3B:6F:36:EB:8D:4F:BC:6F:ED:51:D8:82:C7:15:6C:B5:70:7D:7B:B5:3F:0F:40:F6:27:DE:7C:95\r\na=setup:actpass\r\na=mid:data\r\na=sctpmap:5000 webrtc-datachannel 1024\r\n"}}
scripts/social.js:117 [Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 39516 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 36448 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:4073099051 1 tcp 1518280447 192.168.148.75 0 typ host tcptype active generation 0","sdpMid":"data","sdpMLineIndex":0}}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.663] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 39516 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.664] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 36448 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.664] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:4073099051 1 tcp 1518280447 192.168.148.75 0 typ host tcptype active generation 0","sdpMid":"data","sdpMLineIndex":0}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:3158668251 1 udp 2122260223 192.168.148.75 52952 typ host generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":1,"description":{"type":"answer","sdp":"v=0\r\no=- 4824214638609328095 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=msid-semantic: WMS\r\nm=application 52952 DTLS/SCTP 5000\r\nc=IN IP4 192.168.148.75\r\nb=AS:30\r\na=candidate:3158668251 1 udp 2122260223 192.168.148.75 52952 typ host generation 0\r\na=ice-ufrag:QUnbRUuUO6QZ7ZKp\r\na=ice-pwd:esKsJ3yw6PE7S0zf7V/B+xoQ\r\na=fingerprint:sha-256 44:96:62:2A:0C:49:0B:80:CB:4F:D5:0E:D4:86:DA:7C:0F:BC:71:E2:14:0F:B4:18:95:18:0D:2A:64:F9:89:E7\r\na=setup:active\r\na=mid:data\r\na=sctpmap:5000 webrtc-datachannel 1024\r\n"}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 61586 typ srflx raddr 192.168.148.75 rport 52952 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 49436 typ srflx raddr 192.168.148.75 rport 52952 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:4073099051 1 tcp 1518280447 192.168.148.75 0 typ host tcptype active generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 33602 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 37255 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] received <------ {"type":3001,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 37811 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
social.js:117 [Google] received <------ {"type":3001,"data":{"type":3}}
user.js:173 [User Inf Mally] received client{"userId":"[email protected]","clientId":"[email protected]/uproxyB013CA8B","status":1}
user.js:34 Client already in memory and is unchanged
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.854] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 33602 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.854] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 37255 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.854] rtcNet: handleSignalMessage: 
{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 37811 typ srflx raddr 192.168.148.75 rport 49747 generation 0","sdpMid":"data","sdpMLineIndex":0}}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.854] rtcNet: handleSignalMessage: 
{"type":3}
freedom-for-chrome.js:1110  PeerConnection D [11/30 18:56:29.854] rtcNet: handleSignalMessage: noMoreCandidates
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 32981 typ srflx raddr 192.168.148.75 rport 52952 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.120 48721 typ srflx raddr 192.168.148.75 rport 52952 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":2,"candidate":{"candidate":"candidate:1892174920 1 udp 1686052607 74.125.57.121 37298 typ srflx raddr 192.168.148.75 rport 52952 generation 0","sdpMid":"data","sdpMLineIndex":0}}}
scripts/social.js:117 [Google] sending ------> {"type":3002,"data":{"type":3}}
3scripts/social.js:117 [Google] Running monitor

@iislucas iislucas changed the title Giving consent flow is broken Messages lost in the social provider Jan 2, 2015
@iislucas iislucas changed the title Messages lost in the social provider Signaling messages lost in the social provider Jan 5, 2015
@dborkan dborkan modified the milestones: v0.7 Allardice (sprint), v0.9 Allardice (Web Store Feature Complete) Jan 9, 2015
@dborkan dborkan self-assigned this Jan 9, 2015
@dborkan
Copy link
Contributor

dborkan commented Jan 13, 2015

Changing this from P0 to P1, since most of us are able to use uProxy

@dborkan
Copy link
Contributor

dborkan commented Jan 28, 2015

Closing this issue - we have not been able to replicate this recently, but believe it may have been fixed by freedomjs/freedom-social-xmpp#80 (fix bug where all messages within the same "batch" were being sent to the same destination).

Also we've added integration tests (#753) to help us detect if things break in the future, and fixed our error handling code (freedomjs/freedom-social-xmpp#77) so that we properly print out error messages.

@dborkan dborkan closed this as completed Jan 28, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
P1
Projects
None yet
Milestone
v-focus-2015-02-02
Development

No branches or pull requests
3 participants
@iislucas @dborkan @salomegeo