After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 794815 - Forgive errors when fetching events
Forgive errors when fetching events
Status: RESOLVED FIXED
Product: evolution-ews
Classification: Other
Component: Miscellaneous / EWS Core
3.28.x
Other Linux
: Normal normal
: ---
Assigned To: Evolution EWS maintainer(s)
Evolution EWS maintainer(s)
Depends on:
Blocks:
 
 
Reported: 2018-03-29 15:24 UTC by Niccolas Marcotte
Modified: 2018-04-10 13:46 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
the patch that change a break for a continue (453 bytes, patch)
2018-03-29 15:24 UTC, Niccolas Marcotte
reviewed Details | Review

Description Niccolas Marcotte 2018-03-29 15:24:08 UTC
Created attachment 370304 [details] [review]
the patch that change a break for a continue

Evolution EWS plugin skips prossessing further appointemts when an error occurs in ecb_ews_item_to_component_sync. 

I had no new appointment for a week. Suspecting that something was wrong, I started the calendar-factory in verbose console mode:
EWS_DEBUG=2 /usr/lib/evolution-calendar-factory -w
The logs on the console had me look at the following code : https://git.gnome.org/browse/evolution-ews/tree/src/calendar/e-cal-backend-ews.c?id=daf6f761ac4c07230b682607c8b157ecb4227b8b#n583 

Upon code review I was quickly able to pinpoint where the code gave up on parsing new meetings and make a small patch (see attachment) to have the remainder of the appointments appears in the calendar. 

Sadly I was not able to track down offending meeting. 

Also my patch does not include additional logging, or user notification that there were an error, only the discrete g_warn_if_reached (); It would be really nice to warn the user when something is unparsable, but to do so is beyond my GNOME C skills.
Comment 1 Milan Crha 2018-04-03 13:35:45 UTC
Thanks for a bug report and patch. The only problem with GError is that there is no warning mechanism, the operation result is always either success or failure. The warning might be something in between the two. I sometimes miss the warning mechanism too.

While I agree with your idea, it has some weak points. When the ecb_ews_item_to_component_sync() fails in a way which also sets the GError, then the next failure would try to overwrite the existing error, which results in runtime warning. Thus there might be some pile-up of the errors, unless the returned error is not related to connection issues or such, in which case it doesn't make sense to continue with the processing of the downloaded results. The g_warn_if_reached() you pointed to is there to ensure more investigation will be done in that case, because it's not properly covered there.

Do you still have that EWS_DEBUG=2 log, please? It'll show which of the components failed and their content, even base64 encoded. I'd like to see what the server returned, to verify whether the error is expectable or not, or whether the evolution-ews code is wrong in its assumptions.

You can let it re-download whole calendar content when you remove
   ~/.cache/evolution/calendar/<ews-calendar-uid>/
and then restart the evolution-calendar-factory with EWS debugging on, thus it'll print everything there. The log will be huge, depending when the error happens (ideally run the unpatched evolution-ews version, which will cause early stop and it'll make it slightly easier to identify when the error happened. You can grab it to a file with a command like this:

   $ EWS_DEBUG=2 /usr/lib/evolution-calendar-factory -w &>log.txt

I would not attach it here, because it would be too hard to sanitize it from the private content, but if you do not mind, then you can send it to my bugzilla email, with a reference to this bug report, thus I'd not overlook it in my spam folder. You can even left in the log only the part witht he g_warn_if_reached() runtime warning and the EWS request and response before it and eventually after it as well, in case of some odd output interleaving.
Comment 2 Niccolas Marcotte 2018-04-06 12:54:29 UTC
sorry for the delay....
  I cannot consent for the other peoples in my calendar and we take consent really seriously at my institution. So before sending you those log I would need to blank the emails of those meetings... Do you have a tool to sanitize emails from those logs ?
Comment 3 Niccolas Marcotte 2018-04-06 13:23:02 UTC
If I process the log with a regex that replace all email with email@example.com, would they still be of use to you ?
Comment 4 Milan Crha 2018-04-06 13:28:51 UTC
I understand the privacy reasons, and I agree with you. I do not care of the emails as such, I only want to recognize whether there was any real (and sensible) data or not. Thus even "xxx" would make it. Please note of MimeContent element. It contains the event encoded in base64, thus you cannot just search for emails in the log and if none found then expect none are there. Unfortunately, I need to see the MimeContent, if there, to verify whether it had meaningful and correct data stored there (some exchange servers can return broken iCalendar data, for which a workaround in the code exists, but it looks like your MimeContent is broken in a different way.
Comment 5 Niccolas Marcotte 2018-04-06 13:55:14 UTC
I got the authorization to send you my logs, on the condition that you keep them private. You will received them by email soon
Comment 6 Milan Crha 2018-04-06 15:09:00 UTC
Thanks, I'm not going to share your log with anyone, I already deleted it.

I did let libical parse all the MimeContent-s in the log and it failed on one of them only. It's the item with EWS ID AAMkADNjMDExMWQzLWU5MGItNGQ2MC1iMzEzLWY0OGY2M2VmMDljNwBGAAAAAACb81K9d8rURrKtfmE7SeZkBwBbf06363jLQK0a9OKpjMXuAAAAJLbZAADcJZIUKRjtQpXoAE5QtZyPAAFIqDUIAAA=
and UID 37512f67-8bb2-4883-861a-2d15f9f06673, which has:

   SUMMARY;LANGUAGE=fr-CA:Nicolas Marcotte
   DTSTART;VALUE=DATE:20171121
   DTEND;VALUE=DATE:20171122

The problem with it is that it contains a timezone definition (which is not used) with broken TZID, it contains a garbage at the end of that (I do not know whether browser will show it properly):

   TZID:America/New_York^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@

This, when passed to libical (or printf()), is cut at the end of the 'York' word, having completely broken component to parse. I do not know how this could happen, but it's there, thus it could.

I'll try to find out some way to fix it, on top of your proposed change. Thanks again for your help with this.
Comment 7 Milan Crha 2018-04-09 08:52:35 UTC
I made couple changes here. First of all, when the server claims the MimeContent is UTF-8, but the returned data is not valid UTF-8 string, then it makes it valid. This helped with your event, which should be visible in your calendar after you apply the below change, delete and re-populate the local cache as mentioned above. I also made the code forbid conversion errors, as long as they do not provide GError (which is the case here as well).

I'll appreciate if you could confirm the change and my expectations, because I wasn't able to reproduce this, thus neither properly/fully verify the change. Thanks in advance.

Created commit 7935a22 in ews master (3.29.1+)
Created commit c61a204 in ews gnome-3-28 (3.28.1+)
Comment 8 Niccolas Marcotte 2018-04-10 13:46:13 UTC
It works and I now have the following more informative msg when I start /usr/lib/evolution-calendar-factory -w :
(evolution-calendar-factory-subprocess:30846): ecalbackendews-CRITICAL **: 09:45:58.441: e_cal_backend_ews_tz_util_get_ical_equivalent: assertion 'msdn_tz_location != NULL' failed

(evolution-calendar-factory-subprocess:30846): ecalbackendews-CRITICAL **: 09:45:58.441: e_cal_backend_ews_tz_util_get_ical_equivalent: assertion 'msdn_tz_location != NULL' failed

thank you for the quick resolution