various problems with V3xx

[qratz]

Recently, i was able to the current version of moto-sync along with opensync-0.32 on a kubuntu machine with jahn's packages. The respective versions are: libopensync1 0.32+svn20070730-feisty1 libopensync1-dbg 0.32+svn20070730-feisty1 libopensync-plugin-python 0.31+svn20070703-feisty2 libopensync-plugin-moto 0.31+svn20070724-feisty1

The phone was again a Motorola V3xx. The backup function of mototool worked very well, so i created a sync group to sync the phone with the file-sync plugin. In the middle of the sync the following Exception ocurred:

event sink of member 1 of type moto-sync had an error: Traceback (most recent call last):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2261, in get_changes
    for change in self.access.list_changes(self.objtype):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2099, in list_changes
    entries = [self.__event_from_moto(d, x) for (d, x) in self.comms.read_events()]
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2199, in __event_from_moto
    return PhoneEventExtendedMoto(data, exceptions)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1512, in __init__
    PhoneEventSimpleMoto.__init__(self, data, exceptions)
TypeError: unbound method __init__() must be called with PhoneEventSimpleMoto instance as first argument (got PhoneEventExtendedMoto instance instead)

But the excception did not seem to have a bad effect on the sync process. moto-sync seemed to commit all changes but somewhere at the end of the sync this message ocurred:

data sink of member 1 of type moto-sync had an error: Unable to find sink for data

My moto-sync.conf looked like this:

<config><device>/dev/ttyACM0</device></config>

and the file-sync.conf like this:

<?xml version="1.0"?>
<config>
  <directory>
    <path>/home/sini/test</path>
    <objtype>data</objtype>
  </directory>
<directory>
  <path>/home/sini/test/1</path>
  <objtype>contact</objtype>
  <objformat>vcard30</objformat>
</directory>
<directory>
  <path>/home/sini/test/2</path>
  <objtype>event</objtype>
  <objformat>vevent20</objformat>
</directory>
</config>

I'll also attach the necessary traces.

[andrewb]

Thanks for testing. I've just committed r2371, which should fix the first problem, so please test that... you should be able to grab motosync.py from svn and use it with the packages you have installed.

The second problem I believe is caused by your file-sync config. Try this, and see if it goes away:

<?xml version="1.0"?>
<config>
<directory>
  <path>/home/sini/test/1</path>
  <objtype>contact</objtype>
  <objformat>vcard30</objformat>
</directory>
<directory>
  <path>/home/sini/test/2</path>
  <objtype>event</objtype>
  <objformat>vevent20</objformat>
</directory>
</config>

[qratz]

Just tried the new version of moto-sync.py: The previously reported Exception is gone, but a new one appears at about the same time as the old one:

event sink of member 1 of type moto-sync had an error: Traceback (most recent call last):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2264, in get_changes
    for change in self.access.list_changes(self.objtype):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2102, in list_changes
    entries = [self.__event_from_moto(d, x) for (d, x) in self.comms.read_events()]
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2202, in __event_from_moto
    return PhoneEventExtendedMoto(data, exceptions)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1515, in __init__
    moto_event_simple_init(self, data, exceptions)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1360, in moto_event_simple_init
    event.duration = timedelta(0, 0, 0, 0, data[6])
TypeError: unsupported type for timedelta minutes component: str

I also adjusted the configuration of file-sync to your suggestion, but still nothing gets synced, i.e. no files appear in the directories specified in file-sync.conf. But now, another error ocurrs:

<--- ERROR --- osync_format_env_find_path_formats: Fewer sink_engines reported get_changes than connected

I still don't know if this is because of misconfiguration of the file-sync plugin, or due to an error in file-sync or opensync... Anyways, the new traces are again attached.

[qratz]

2. set of traces

[qratz]

2. set of traces

[qratz]

2. set of traces

[qratz]

2. set of traces

[andrewb]

Hi,

regarding the first problem (traceback from motosync.py), the data being returned by your phone isn't how I expect it, or I'm parsing it wrong. Unfortunately I can't see what's happened, because this is a sensitive trace. Can you do another trace with the sensitive data included, and find just these lines:

[1185918577.861295]                                             [SENSITIVE CONTENT HIDDEN]
  534
[1185918577.867894]                                             [SENSITIVE CONTENT HIDDEN]
  535
[1185918577.872725]                                             [SENSITIVE CONTENT HIDDEN]
  536
[1185918577.874831]                                             [SENSITIVE CONTENT HIDDEN]
  537
[1185918577.877581]                                             >>>>>>>  osync_context_report_osyncerror(0x8169020, 0x816b608:(Traceback (most recent call last):
  538
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2264, in get_changes
  539
    for change in self.access.list_changes(self.objtype):
  540
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2102, in list_changes
  541
    entries = [self.__event_from_moto(d, x) for (d, x) in self.comms.read_events()]
  542
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2202, in __event_from_moto
  543
    return PhoneEventExtendedMoto(data, exceptions)
  544
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1515, in __init__
  545
    moto_event_simple_init(self, data, exceptions)
  546
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1360, in moto_event_simple_init
  547
    event.duration = timedelta(0, 0, 0, 0, data[6])
  548
TypeError: unsupported type for timedelta minutes component: str

One of the sensitive lines above should be an AT+MDBR commnd. I am interested in the format and type of the data that is returned there. You could either edit the data itself to hide your event details (eg. change the descriptions and times), or if you're comfortable emailing it to me at andrewb AT cse.unsw.edu.au.

Regarding the second error, did you re-run discovery after changing the file-sync configuration?

Andrew

[qratz]

The lines marked SENSITIVE before the Excpetion ocurrs are:

[SENSITIVE] --> AT+MDBR=0,14
[SENSITIVE] <-- +MDBR: 0,006B006900720069006C,1,0,"22:00","07-27-2007",,"06:28","02-06-2088",0,"23:00","07-27-2007","",0,,,501,0,0,,"00-00-2000"
[SENSITIVE] <-- +MDBR: 1,005000610072006B00650074,1,1,"18:00","07-30-2007",,"17:30","07-30-2007",0,"19:00","07-30-2007","",0,,,501,0,0,,"00-00-2000"
[SENSITIVE] <-- OK

These are the original lines. i did not manupulate anything... They look kinda strange though. As far as i remember, the title of the event should be where the huge hex number is?!

[andrewb]

This should be fixed by r2416. Please try again.

The "huge hex number" is a utf16-encoded version of the event title. I switched character encodings, because it avoids problems with things like quotation marks and newline characters in string fields.

[qratz]

Alright, just tried the newest version. The first sync runs beautifully, no exceptions, contacts and events get synced to file. Then i tried to immediately sync again, to check whether moto-sync reacts correctly when nothing is changed since the last sync. Unfortunately, this is where a lot of Excpetions appear. Basically two Exceptions appear repeatedly:

0xb1b47d60:(Traceback (most recent call last):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2292, in commit
    success = self.access.update_entry(change, ctx)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2152, in update_entry
    entry = PhoneContactXML(change.data.data, self.revcategories)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1806, in __init__
    self.firstlast_index = self.name.index(getField('Name', 'LastName'))
TypeError: expected a character buffer object
))

and

pm_call_module_method: Traceback (most recent call last):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2292, in commit
    success = self.access.update_entry(change, ctx)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2148, in update_entry
    entry = PhoneEventExtendedXML(change.data.data)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1546, in __init__
    xmlevent_to_moto_simple(node, self)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 693, in xmlevent_to_moto_simple
    event.eventdt = parse_ical_time(getField('DateStarted'))
  File "/usr/lib/opensync/python-plugins/motosync.py", line 281, in parse_ical_time
    d = dateutil.parser.parse(timestr)
  File "/var/lib/python-support/python2.4/dateutil/parser.py", line 700, in parse
    return DEFAULTPARSER.parse(timestr, **kwargs)
  File "/var/lib/python-support/python2.4/dateutil/parser.py", line 300, in parse
    res = self._parse(timestr, **kwargs)
  File "/var/lib/python-support/python2.4/dateutil/parser.py", line 348, in _parse
    l = _timelex.split(timestr)
  File "/var/lib/python-support/python2.4/dateutil/parser.py", line 139, in split
    return list(cls(s))
  File "/var/lib/python-support/python2.4/dateutil/parser.py", line 133, in next
    token = self.get_token()
  File "/var/lib/python-support/python2.4/dateutil/parser.py", line 64, in get_token
    nextchar = self.instream.read(1)
AttributeError: 'NoneType' object has no attribute 'read'

I'll attach the trace files in an archive this time. I cut out sensitive information by hand (you'll see the SNIPSNIPSNIP :) )

[andrewb]

Ok, the first error has been fixed. The second is caused by an event that has no <DateStarted?> node in the XML; this is invalid. I've added an assertion to make the error more obvious, however looking at the trace logs I believe the real culprit here is the vformat converter. moto-sync is being handed event nodes that look like this:

<?xml version="1.0"?>
<event>
  <Categories>
    <Category>Algemein</Category>
  </Categories>
</event>

... which is clearly bogus. There are missing parts in the vformat converter, but I have never seen it generate something so useless, so I suggest you have a look at your vcard files in the file-sync dir, see if they are sane, and if so, try running vconvert --to-xmlformat on them, and reporting any bugs against the vformat converter plugin.

However, for testing moto-sync independently, you can just change file-sync to store the native xmlformats. The way to do this is something like:

<?xml version="1.0"?>
<config>
  <directory>
    <path>foo</path>
    <objtype>contact</objtype>
    <objformat>xmlformat-contact</objformat>
  </directory>
  <directory>
    <path>bar</path>
    <objtype>event</objtype>
    <objformat>xmlformat-event</objformat>
  </directory>
</config>

Thanks again for continuing to test this!

[qratz]

LOL, human stupidity is the reason for the strange vformat conversion error... Somewhere in those nights after work, when i tend to test moto-sync, i changed the file-sync configuration so that the contacts and events were stored in the same directory... stupid me. So think opensync tried to convert the vevent two times, to xmlcontact and once to xmlevent.... I think i'll still post a bugreport, as i think that such an obvious misconfiguration should somehow be detected by file-sync. However, i got to test moto-sync with the correct configuration: Reading and writing contacts workd beatifully. Reading events works. Writing calendar events doesn't. The following Errors ocurrs:

[SENSITIVE] --> AT+MDBL=0
[SENSITIVE] <-- ERROR
[SENSITIVE] --> AT+MDBWE=3,0,0
[SENSITIVE] <-- ERROR

so i think these two commands don't work anymore on the new motorolas. However, i opened a serial console to the phone change to mode 2 (at+mode=2) and then immedietly entered the following command:

at+mdbw=4,"Flight",1,1,"19:20","08-07-2007",,"18:50","08-07-2007",0,"22:20","08-07-2007","",7,"FRA","SOFIA",501,0,0,,"00-00-2000"

This procedure worked. The entry was perfectly available on the phone's calendar. Unfortunatly i have yet to find out how to delete entries. i tried to overwrite an entry with what i hoped were the default variables of an event entry:

at+mdbw=4,"",1,0,"06:28","02-06-2088",,"06:28","02-06-2088",0,"06:28","02-06-2088","",0,"","",501,0,0,,"00-00-2000"

and

at+mdbw=4,"",1,0,"00:00",00-00-2000",,"06:28","02-06-2088",0,"00:00","00-00-2000","",0,"","",501,0,0,,"00-00-2000"

But that didn't work. Maybe you have an idea? I won't be able to do further testing for a week, as i'm going on vacation for a week. Next week i'll respond again :).

[andrewb]

Hmm. What does the windows tool do if you delete an event? What does it do if you just write one? I always delete an event before writing it, because this matches what the windows tool did, but if that's not true for your phone let me know and I'll change it.

I have no other ideas, but the use of the MDBWE command always confused me. It is used both to delete events (AT+MDBWE=n,0,0) and also to write exception entries associated with a particular event (AT+MDBWE=n,e,1) where n is the event number and e is the exceptional occurrence of the event.

Enjoy your holiday :)

[qratz]

Well, the phone came with the Motorola Phone Tools. Is there a way to sniff the traffic between the phone and the Windows tool? If so, i'll gladly try it, when i'm back.

[andrewb]

Yes, actually it's really easy. There is a menu option (sorry, I forget what it's called) that brings up a log window with all the communication with the phone.

[qratz]

So, I'm back from my holiday and as promised immidiately fired up some windows machine and checked what the motorola utility is doing to my phone :). I'll attach a stripped down log form various actions i did on the phone. The log file is commented by me and only my personal data is cut out. Strangly, the windows tool uses AT+MDBWE=X,0,0 to delete events, but it executes quite often an ATE0 command, which, up till now, haven't checked out. If you need me to try some commands on the phone, i'll gladly do so...

[qratz]

LOG of the Motorola Phone Tools for Windows

[andrewb]

ATE0 is a standard AT command that disables echo of the command strings. I don't know why the windows tool sends it so frequently, but I think we can ignore it.

Looking back at what you posted, this log is very odd:

[SENSITIVE] --> AT+MDBL=0
[SENSITIVE] <-- ERROR
[SENSITIVE] --> AT+MDBWE=3,0,0
[SENSITIVE] <-- ERROR

Was that really what happened? AT+MDBL is the command to lock/unlock the calendar. It is tested once at initialisation time (to see if it is required), but should not be issued again later. What is particularly strange is that this log shows moto-sync unlocking the calendar immediately before issuing the AT+MDBWE command. My reading of the code suggests that shouldn't be possible.

Can you please make sure you are using the latest version of moto-sync from svn, and then send me the full trace (by private mail or with obscured event data if you prefer)?

[qratz]

You are right the aforementioned concerning AT+MDBL=0 was from a previous log. Today i had the time to analyze the problem further. The method write_event tries to delete the event at a certain position before actually writing the new event. When trying to write an event to a position that is unused, the phone returns some kind of +CME error and the method breaks before getting to write the event. As far as i can see, the method delete_event(self, pos) should first see whether the given position is empty or used, by using the AT+MDBR command. Deleting an event that actually exists on the phone works flawlessly with AT+MDBWE=x,0,0 For further testing i uncommented the line that calls delete_event in write_event. Now moto-sync actually tried to write to the phone but another error occured. The comma seperated list that is passed to AT+MDBW does not match the phone specs. Two errors are present: The seventh entry (to be clear: data[6]) should be empty, while it currently is an empty string. The same applies to the second last entry. To avoid misunderstandings, here is an example:

moto-sync delivers:

0,"Al Capone",0,0,"00:00","01-24-2007","","06:28","02-06-2088",6,"00:00","01-25-2007","",4,"","",501,0,0,"","00-00-2000"

while it should deliver:

0,"Al Capone",0,0,"00:00","01-24-2007",,"06:28","02-06-2088",6,"00:00","01-25-2007","",4,"","",501,0,0,,"00-00-2000"

[andrewb]

Sorry for the delay replying. r2485 should fix the second problem you encountered.

I'm still working on a fix for the problem with deleting events that haven't been written, because I want to do it without slowing the sync down even further by adding another round-trip command sequence to test if the event is in use. We have the information about what events are occupied, but it needs some changes to the code structure to pass that down to the bottom layer.

In the meantime, please try this change but keep your current fix for that problem.

[qratz]

So far so good... Commenting out the line form write_event that should clear the write position on the phone, committing events to the phone works. I still haven't had the time to do some thorough testing. But i found two strange things: 1) When an event on the phone has a title, location, or note that just contains digits, i get some kind of string conversion error:

osync_context_report_osyncerror(0x819fd48, 0x81ad830:(Traceback (most recent call last):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2275, in get_changes
    for change in self.access.list_changes(self.objtype):
  File "/usr/lib/opensync/python-plugins/motosync.py", line 2122, in list_changes
    xmldata = entry.to_xml().toxml()
  File "/usr/lib/opensync/python-plugins/motosync.py", line 1503, in to_xml
    appendXMLTag(doc, e, 'Content', self.note)
  File "/usr/lib/opensync/python-plugins/motosync.py", line 227, in appendXMLTag
    e.appendChild(doc.createTextNode(text.encode('utf8')))
AttributeError: 'int' object has no attribute 'encode'
))

2) I created a dummy event on the phone, which is just comprised of a title. So no location or note has been set. After syncing to file i get the following file:

BEGIN:VCALENDAR
PRODID:-//OpenSync//NONSGML OpenSync vformat 0.3//EN
VERSION:2.0
BEGIN:VEVENT
CATEGORIES:Private
DTEND:20070825T070000Z
DTSTART:20070825T060000Z
LOCATION:
SUMMARY:SomeTitle
SUMMARY:
END:VEVENT
END:VCALENDAR

I removed that file from the file-sync directory, and synced again. The event got deleted on the phone. Then i moved that file back into file-sync's directory. The event appeared on the phone again. But, on the phone, the event suddenly had note entry. This entry was diplayed as a square. Much like on windows, when a letter is not available. This is what moto-sync send to the phone:

AT+MDBW=1,0053006F006D0065005400690074006C0065,1,0,"08:00","08-25-2007",,"00:00","00-00-2000",0,"09:00","08-25-2007","",1,,"SomeTitle",501,0,0,,"00-00-2000"

First of all, i think that the title is being sent to the phone, as title and as note of the event. And second, if "SomeTitle?" is sent to the phone, why doesn't the string appear there. Maybe because of the mixture of sending String for the comment, while using the hexform the title? Not sure... Btw. while testing i found out another little thing. Line 1774 of motosync.py states the following:

if len(data) >= 25:
    assert(data[24] == '') # unknown? old phones don't have it

data[24] contains the path to the ringtone that is assigned to the respective contact. So you need to change that line, otherwise an assertion error will occur, when a ringtone is set for a contact.

[andrewb]

Sorry for the delay responding to this. I'm in the process of moving overseas, and won't have time to look at it until next week at the earliest. Realistically it will probably be two more weeks until I get back to this.

[andrewb]

Oops, seems "two more weeks" turned into almost exactly "two months", and I've lost track of what still needs fixing. After reading the comment thread, I think this summarises the outstanding problems:

1. write_event should not delete a non-existent event before writing the new one
2. strings that contain only digits get parsed as integers, causing an exception later on
3. the XML field Summary is incorrectly used for both the title of an event and its extended note
4. field 24 of the contact data contains a ringtone path, so we shouldn't assert that it is empty

I've just committed r2733, which should fix 3 and 4 above. 1 and 2 are still outstanding. Please correct me if I've missed anything else.

[qratz]

Nice to see you're back :). I apologize for my late response. Last week my second (not kidding) v3xx broke and i got my replacement today. So much for the quality of this device :). Anyway you didn't miss anything. Issues 3 and 4 are in fact fixed. I hope you'll fix the other issues soon, especially number one, which is a major blocker.

[andrewb]

Ok, for the remaining issues:

• Issue 1 should be fixed by r2877 -- please let me know how that goes.
• Issue 2 (strings containing only digits) is a strange one. Looking at the source to attempt to fix this, it looks like the code is there to handle such a case. Maybe I fixed it at some point but never updated the bug. Can you please check if it still occurs, and reopen the bug if so?