Bug 8980 - "General error" received while placing GV call
: "General error" received while placing GV call
Status: RESOLVED FIXED
Product: The One Ring
General
: unspecified
: N900 Maemo
: High normal with 1 vote (vote)
: ---
Assigned To: Ed Page
: general
:
:
: 8797
:
  Show dependency tree
 
Reported: 2010-02-10 23:21 UTC by thom.kaufmann
Modified: 2010-03-05 05:15 UTC (History)
3 users (show)

See Also:


Attachments
Log from monitoring DBus during a "General Error" (42.63 KB, text/plain)
2010-03-02 04:58 UTC, Ed Page
Details
Log from monitoring DBus during a normal call (79.88 KB, text/plain)
2010-03-02 04:59 UTC, Ed Page
Details
The One Ring log during a "general error" (27.26 KB, text/plain)
2010-03-02 04:59 UTC, Ed Page
Details
The One Ring log during after the "general error" when a call actually went through (30.08 KB, text/plain)
2010-03-02 05:00 UTC, Ed Page
Details
DBus Monitoring Log for SIP on Ubuntu 9.04 (934.24 KB, text/plain )
2010-03-03 14:57 UTC, Ed Page
Details
DBus Monitoring Log for Skype on Maemo 5 (55.01 KB, text/plain )
2010-03-03 14:58 UTC, Ed Page
Details


Note

You need to log in before you can comment on or make changes to this bug.


Description thom.kaufmann (reporter) 2010-02-10 23:21:48 UTC
SOFTWARE VERSION:
(Settings > General > About product)
Maemo 5: 2.2009.51-1.002

EXACT STEPS LEADING TO PROBLEM: 
(Explain in detail what you do (e.g. tap on OK) and what you see (e.g. message
Connection Failed appears))
1. Enable TOR account.
2. Open Contacts application.
3. Select contact name.
4. Select "Google Voice call"

EXPECTED OUTCOME:
Call is placed, "Call disconnected" message is received, and incoming call from
GV is received.

ACTUAL OUTCOME:
"General error" received and calling process is canceled.

REPRODUCIBILITY:
(always, less than 1/10, 5/10, 9/10)
Reproducibility is very high (9/10) on the initial attempt and much lower
(3/10) on the second attempt.
EXTRA SOFTWARE INSTALLED:

OTHER COMMENTS:

User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US;
rv:1.9.2) Gecko/20100115 Firefox/3.6
Comment 1 Ed Page 2010-03-02 04:58:54 UTC
Created an attachment (id=2394) [details]
Log from monitoring DBus during a "General Error"
Comment 2 Ed Page 2010-03-02 04:59:28 UTC
Created an attachment (id=2395) [details]
Log from monitoring DBus during a normal call
Comment 3 Ed Page 2010-03-02 04:59:41 UTC
Created an attachment (id=2396) [details]
The One Ring log during a "general error"
Comment 4 Ed Page 2010-03-02 05:00:01 UTC
Created an attachment (id=2397) [details]
The One Ring log during after the "general error" when a call actually went
through
Comment 5 Ed Page 2010-03-02 05:14:54 UTC
I've attached some logs from my most recent debug session.  It looks like
Mission Control is telling the UI that there is no "InitiatorHandle" but
nothing different was returned from The One Ring either time.

On good call:
New Media channel created at 19:02:07
Request Streams Returned at 19:02:12

On bad call
New Media channel created at 18:49:23
Channel closed unexpectedly at 18:49:26

Just a matter of a few seconds, nothing weird there.

On a good call, GetAll/GetLocalPendingMembersWithInfo seems to be called twice.
 The second set of calls happened about 3 seconds after the first.  The close
happened 2 seconds after the first batch of calls.

I would guess its an issue in RTComm that originates in the code that initiates
that second batch of GetAll/GetLocalPendingMembersWithInfo.

I'm going to try and get the TOR working on the latest Empathy (See by 8797) to
see if I get reproductions.  If not, I'll start hounding on Maemo/Telepathy
mailinglists to see if I can get any word from them on what is going on.
Comment 6 Ed Page 2010-03-03 04:54:37 UTC
Due to 8797, I went ahead and asked around on the maemo-dev mailing list and am
waiting for a reply.
http://lists.maemo.org/pipermail/maemo-developers/2010-March/025032.html
Comment 7 Venomrush 2010-03-03 06:44:47 UTC
I only get General Error message when dialling when I do not have permission to
do something by the carrier's network.

For example, if I set to hide my phone number when dialing = enabled, but the
network does not let me hide my number, I will always get General Error when
attempting to dial until I disable the hide number on the phone.
Comment 8 Lassi Syrjälä nokia 2010-03-03 08:22:03 UTC
Hi,

Looking at the log, the problem is that the properties returned for GetAll()
aren't properly prefixed. If you search for InitiatorHandle, you can see that
in NewChannels, the properties are prefixed with
"org.freedesktop.Telepathy.Channel." whereas in GetAll() the prefixes are
missing from all properties except the ChannelType.
Comment 9 Lassi Syrjälä nokia 2010-03-03 08:30:15 UTC
(In reply to comment #7)
> I only get General Error message when dialling when I do not have permission to
> do something by the carrier's network.

Please file this one separately, seems we should map that error code to a more
descriptive UI string. It would help if you could find the error code using
dbus-monitor (grep for "com.nokia.csd.Call.Error.")
Comment 10 Ed Page 2010-03-03 14:57:37 UTC
Created an attachment (id=2410) [details]
DBus Monitoring Log for SIP on Ubuntu 9.04

GetAll does not fully qualify the property names but this is older software
Comment 11 Ed Page 2010-03-03 14:58:33 UTC
Created an attachment (id=2411) [details]
DBus Monitoring Log for Skype on Maemo 5

Skype is less mature of CMs but it also does not fully qualify the property
names
Comment 12 Ed Page 2010-03-03 15:05:44 UTC
(In reply to comment #8)
> Looking at the log, the problem is that the properties returned for GetAll()
> aren't properly prefixed. If you search for InitiatorHandle, you can see that
> in NewChannels, the properties are prefixed with
> "org.freedesktop.Telepathy.Channel." whereas in GetAll() the prefixes are
> missing from all properties except the ChannelType.

Thanks for your quick feedback on this.  Unfortunately I'm wondering if this is
the issue
1) The formatting for the property names is done by telepathy-python (but tp is
still fairly immature)
2) Because this is controlled by tp, all my GetAll's are returning properties
formatted like that which would imply all would fail.  This also applies to
butterfly and sunshine connection managers (MSN and GaduGadu)
3) An older Sofia returns properties in the same manner, see attachment
4 [details]) An immature Spirit returns properties in the same manner, see attachment

Since GetAll is relative to a particular interface while NewChannel can report
properties for any of the interfaces, it makes sense that they would not have
to be fully qualified.
Comment 13 Lassi Syrjälä nokia 2010-03-03 15:30:04 UTC
(In reply to comment #12)
> Since GetAll is relative to a particular interface while NewChannel can report
> properties for any of the interfaces, it makes sense that they would not have
> to be fully qualified.

You may be right about that. However, from the Phone application point of view,
the problem is simply that the properties hash passed to HandleChannels() does
not seem to contain the (fully qualified) .InitiatorHandle property, or that
tp_asv_get_uint32() returns FALSE for validity.

The UI then returns an error to MC:
error sender=:1.208 -> dest=:1.18
error_name=org.freedesktop.Telepathy.Error.InvalidArgument reply_serial=8518
   string "No InitiatorHandle"

Which MC propagates as:
method call sender=:1.18 -> dest=org.freedesktop.Telepathy.Client.CallUI
serial=8530 path=/org/freedesktop/Telepathy/Client/CallUI;
interface=org.freedesktop.Telepathy.Client.Interface.Requests;
member=RemoveRequest
   object path "/com/nokia/MissionControl/requests/r20"
   string "com.nokia.MissionControl.Errors.ChannelRequestGenericError"
   string "Handle channel failed: No InitiatorHandle"

--
Btw, what's this in the other log?

(18:49:23) WARNING:channel.call:InitiatorID or InitiatorHandle not set on new
channel, assuming locally initiated
Comment 14 Lassi Syrjälä nokia 2010-03-03 15:38:27 UTC
(In reply to comment #13)
> The UI then returns an error to MC:
> error sender=:1.208 -> dest=:1.18
> error_name=org.freedesktop.Telepathy.Error.InvalidArgument reply_serial=8518
>    string "No InitiatorHandle"

If you look up the matching method call for this serial number, there's indeed
no .InitiatorHandle in the properties.
Comment 15 Ed Page 2010-03-04 05:17:59 UTC
So it seems that there is a race condition between The One Ring returning the
results of the GetAll (Reply 8548 in the good log, 8516 in the bad log) and
"1.18"'s "HandleChannels" passing its data.

Good Log Summary:
1.18 -> TOR: CreateChannel
TOR broadcasts GroupFlagsChanged
TOR broadcasts Members Changed
TOR -> 1.18: CreateChannel returns
1.18 -> TOR: GetAll (Channel)
TOR broadcasts NewChannels
TOR broadcasts NewChannel
TOR -> 1.18: GetAll (Channel) returns
1.18 -> TOR: GetAll (Group)
TOR -> 1.18: GetAll (Group) returns
1.18 -> TOR: GetGroupFlags
TOR -> 1.18: GetGroupFlags returns
1.18 -> TOR: GetSelfHandle
TOR -> 1.18: GetSelfHandle returns
1.18 -> TOR: GetAllMembers
TOR -> 1.18: GetAllMembers returns
1.18 -> TOR: GetLocalPendingMembersWithInfo
TOR -> 1.18: GetLocalPendingMembersWithInfo returns
1.18 broadcasts HandleChannels

Bad Log Summary
1.18 -> TOR: CreateChannel
TOR broadcasts GroupFlagsChanged
TOR broadcasts Members Changed
TOR -> 1.18: CreateChannel returns
1.18 -> TOR: GetAll (Channel)
TOR broadcasts NewChannels
TOR broadcasts NewChannel
1.18 broadcasts HandleChannels
TOR -> 1.18: GetAll (Channel) returns
1.18 -> TOR: GetAll (Group)
TOR -> 1.18: GetAll (Group) returns
1.18 -> TOR: GetGroupFlags
TOR -> 1.18: GetGroupFlags returns
1.18 -> TOR: GetSelfHandle
TOR -> 1.18: GetSelfHandle returns
1.18 -> TOR: GetAllMembers
TOR -> 1.18: GetAllMembers returns
1.18 -> TOR: GetLocalPendingMembersWithInfo
TOR -> 1.18: GetLocalPendingMembersWithInfo returns
1.208 -> TOR: GetStatus
1.18 -> TOR: Close
TOR broadcasts Closed

For both cases, the TOR logging reports these things to be happening within the
same second.  So I guess the question is why is 1.18 signalling HandleChannels,
passing back the data with incomplete data before TOR gets a chance to reply to
the GetAll.  My shot in the dark guess is 1.18 blindly returns whatever
parameters its received and does not properly block on GetAll's reply, causing
this race condition.

The following line in the TOR logging:
(19:02:07) WARNING:channel.call:InitiatorID or InitiatorHandle not set on new
channel, assuming locally initiated
Happens for both the good and bad case.  It creator of the channel didn't
include the InitiatorID with all of the rest of the properties.  I already have
enough info to infer it, so I do that.
Comment 16 Lassi Syrjälä nokia 2010-03-04 09:12:16 UTC
Presumably :1.18 (aka MC) calls HandleChannels() with the information returned
by TOR in its reply to CreateChannel(). NewChannels is ignored, and all the
introspection seen in the logs is for MC's own benefit.

I bet the problem (and many redundant method calls) go away, if if you make TOR
supply enough information in reply to CreateChannel().

> The following line in the TOR logging:
> (19:02:07) WARNING:channel.call:InitiatorID or InitiatorHandle not set on new
> channel, assuming locally initiated
> Happens for both the good and bad case.  It creator of the channel didn't
> include the InitiatorID with all of the rest of the properties.  I already have
> enough info to infer it, so I do that.

The properties are meant to be included by the connection manager, and it
should actually fail a request containing them.

"It does not make sense for this property to be in channel requests - the
initiator will always be the local user - so it MUST NOT be accepted."
Comment 17 Ed Page 2010-03-04 14:12:04 UTC
(In reply to comment #16)
> Presumably :1.18 (aka MC) calls HandleChannels() with the information returned
> by TOR in its reply to CreateChannel(). NewChannels is ignored, and all the
> introspection seen in the logs is for MC's own benefit.

This is one part that I find kind of annoying in the telepathy spec, its very
ambiguous about what to do with properties.

Interestingly enough it is telepathy-python that decides just to take the
properties returned by CreateChannel, filter out the mutable ones, and return
that.  I find it kind of funny that it does that seeing as how the person
requesting the channel should already know what those properties are.  I do
think it makes more sense to ask the Channel for the immutable properties like
it does for NewChannels

Lucky for me (and to the annoyance of the maintainer) I ship a copy of all of
their helper classes so I can fix these issues as I come across them.  I will
then push out to my tor_fixes branch on github and request a pull.  I know
butterfly has been adding support for StreamedMedia and would be hit by a
similar issue.

> I bet the problem (and many redundant method calls) go away, if if you make TOR
> supply enough information in reply to CreateChannel().

It seems odd that it would notice its missing information, request that
information, and then signal HandleChannels without waiting for it.  I would
think MC should either handle this more gracefully and wait for those
outstanding requests or not do those extra requests and fail more loudly.
Comment 18 Ed Page 2010-03-04 14:37:48 UTC
(In reply to comment #16)
> The properties are meant to be included by the connection manager, and it
> should actually fail a request containing them.
> 
> "It does not make sense for this property to be in channel requests - the
> initiator will always be the local user - so it MUST NOT be accepted."

Maybe telepathy-butterfly is adding Initiator at another point but the
constructor to their StreamedMedia channel requires InitiatorId or
InitiatorHandle in the properties.  In creating my StreamedMedia channel I
followed course, found that I didn't have incoming Initiator info, so added a
workin else clause which prints that message to the log.
Comment 19 Lassi Syrjälä nokia 2010-03-04 15:52:15 UTC
(In reply to comment #17)
> It seems odd that it would notice its missing information, request that
> information, and then signal HandleChannels without waiting for it.  I would
> think MC should either handle this more gracefully and wait for those
> outstanding requests or not do those extra requests and fail more loudly.

I think MC just instantiates a TpChannel which starts furiously pulling
information that it wasn't provided to begin with.
Comment 20 Ed Page 2010-03-05 05:14:51 UTC
0.8.4 is now in extras-devel with all properties being returned when
CreateChannel is called.  If I don't hear of any further issues, I'll put a git
repo up and post on the telepathy list about the bug in telepathy-python