[Home]

Summary:ASTERISK-16881: EWS Write Causes Segfault
Reporter:Andrew Parisio (parisioa)Labels:
Date Opened:2010-10-27 10:02:52Date Closed:2013-01-14 14:42:44.000-0600
Priority:CriticalRegression?No
Status:Closed/CompleteComponents:Resources/res_calendar
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:If i try and do a write to the calendar it fails and segfaults.  Also calendar show calendar does not properly show busy state as if it is unable to read from the calendar either.  

Console will intermittently show connection errors like this but not crash:
Unable to communicate with Exchange Web Service at 'https://mail.mydomain.com/ews/Exchange.asmx': Could not read status line: connection timed out


****** ADDITIONAL INFORMATION ******

[testcalendar]
type = ews               ; type of calendar--currently supported: ical, caldav, exchange, or ews
url = https://mail.mydomain.com/ews/Exchange.asmx ; URL to MS Exchange EWS
user = andrewp              ; Exchange username
secret = passwordmasked        ; Exchange password
refresh = 1             ; refresh calendar every n minutes
timeframe = 6000           ; number of minutes of calendar data to pull for each refresh period


extensions.conf:
exten => 1,1,Set(CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= "My event","mailto:andrewp@mydomain.com",228383580,228383640,1))



the only real output in messages

[Oct 27 07:57:48] DEBUG[20950] pbx.c: Launching 'Set'
[Oct 27 07:57:48] DEBUG[20950] res_calendar_ews.c: EWS: HTTP request...
[Oct 27 07:57:48] DEBUG[20950] res_calendar_ews.c: <soap:Envelope xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:t="http://schemas.microsoft.com/exchange/services/2006/types"><soap:Body><CreateItem xmlns="http://schemas.microsoft.com/exchange/services/2006/messages" xmlns:t="http://schemas.microsoft.com/exchange/services/2006/types" SendMeetingInvitations="SendToNone" ><SavedItemFolderId><t:DistinguishedFolderId Id="calendar"/></SavedItemFolderId><Items><t:CalendarItem xmlns="http://schemas.microsoft.com/exchange/services/2006/types"><Subject> My event</Subject><Body BodyType="Text"></Body><ReminderIsSet>false</ReminderIsSet><Start>1977-03-28T07:53:00Z</Start><End>1977-03-28T07:54:00Z</End><IsAllDayEvent>false</IsAllDayEvent><LegacyFreeBusyStatus>Tentative</LegacyFreeBusyStatus><Location></Location></t:CalendarItem></Items></CreateItem></soap:Body></soap:Envelope>


console output:

   -- Executing [1@from-staff:1] Set("SIP/1500-00000000", "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= "My event","mailto:andrewp@mydomain.com",228383580,228383640,1)") in new stack
[Oct 27 08:03:26] WARNING[20994]: res_calendar_ews.c:530 send_ews_request_and_parse: Unable to communicate with Exchange Web Service at 'https://mail.mydomain.com/ews/Exchange.asmx': Could not read status line: connection timed out
Segmentation fault (core dumped)
Comments:By: Andrew Parisio (parisioa) 2010-10-27 10:03:34

Whoops, forgot to add that it fails somewhere in the 60 to 120 second range repeatedly.

happens on completely different 07 and 2010 exchange servers


By: Andrew Parisio (parisioa) 2010-10-27 15:26:47

Here is a backtrace, dont_opt & debug threads were enabled.


#0  0x00007f7e21dc00b0 in strlen () from /lib/libc.so.6
#1  0x00007f7e21d8cae0 in vfprintf () from /lib/libc.so.6
#2  0x00007f7e21db226a in vsnprintf () from /lib/libc.so.6
#3  0x00007f7df834fef9 in ne_vsnprintf (str=0x1038 <Address 0x1038 out of bounds>,
   size=140179011920729, fmt=0x40d95b98 "8\020", ap=0x0) at ne_string.c:531
#4  0x00007f7df834f897 in ne_set_error (sess=<value optimized out>, format=<value optimized out>)
   at ne_session.c:353
ASTERISK-1  0x00007f7df834c99d in aborted (req=<value optimized out>,
   doing=0x7f7df835e4cf "Could not read status line", code=<value optimized out>)
   at ne_request.c:208
ASTERISK-2  0x00007f7df834dabe in send_request (req=0x88b8f10, request=0x8886fb0) at ne_request.c:896
ASTERISK-3  0x00007f7df834ea81 in ne_begin_request (req=0x88b8f10) at ne_request.c:1189
ASTERISK-4  0x00007f7df8357af5 in ne_xml_dispatch_request (req=0x88b8f10, parser=0x88a9340) at ne_xmlreq.c:87
ASTERISK-5  0x00007f7df834ae38 in send_ews_request_and_parse (request=0x7f7e1c6ea810, ctx=0x40d95e60)
   at res_calendar_ews.c:528
ASTERISK-6 0x00007f7df834b20e in ewscal_write_event (event=0x7f7e1c6d1358) at res_calendar_ews.c:624
ASTERISK-7 0x00007f7e1a24a969 in calendar_write_exec (chan=0x7f7e1c6813a8, cmd=0x40d96160 "CALENDAR_WRITE",
   data=0x40d9616f "testcalendar",
   value=0x40d963e3 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)")
   at res_calendar.c:1353
ASTERISK-8 0x0000000000504d8b in ast_func_write (chan=0x7f7e1c6813a8,
   function=0x40d96270 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)",
   value=0x40d963e3 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)")
---Type <return> to continue, or q <return> to quit---
   at pbx.c:3572
ASTERISK-9 0x000000000051920c in pbx_builtin_setvar_helper (chan=0x7f7e1c6813a8,
   name=0x40d963a0 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)",
   value=0x40d963e3 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)")
   at pbx.c:9488
ASTERISK-10 0x0000000000519719 in pbx_builtin_setvar (chan=0x7f7e1c6813a8,
   data=0x40d98700 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:9562
ASTERISK-11 0x00000000004fcb09 in pbx_exec (c=0x7f7e1c6813a8, app=0x7f7e1c4c56d0,
   data=0x40d98700 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:1399
ASTERISK-12 0x00000000005066b0 in pbx_extension_helper (c=0x7f7e1c6813a8, con=0x0,
   context=0x7f7e1c681900 "from-staff", exten=0x7f7e1c681950 "1", priority=1, label=0x0,
   callerid=0x7f7e1c6a8570 "1500", action=E_SPAWN, found=0x40d9aed0, combined_find_spawn=1)
   at pbx.c:4078
ASTERISK-13 0x000000000050806e in ast_spawn_extension (c=0x7f7e1c6813a8,
   context=0x7f7e1c681900 "from-staff", exten=0x7f7e1c681950 "1", priority=1,
   callerid=0x7f7e1c6a8570 "1500", found=0x40d9aed0, combined_find_spawn=1) at pbx.c:4577
ASTERISK-14 0x0000000000508b15 in __ast_pbx_run (c=0x7f7e1c6813a8, args=0x0) at pbx.c:4675
ASTERISK-15 0x000000000050a79d in pbx_thread (data=0x7f7e1c6813a8) at pbx.c:4986
ASTERISK-16 0x000000000055ed0b in dummy_start (data=0x7f7e1c6e52c0) at utils.c:971
ASTERISK-17 0x00007f7e215cffc7 in start_thread () from /lib/libpthread.so.0
ASTERISK-18 0x00007f7e21e1464d in clone () from /lib/libc.so.6
---Type <return> to continue, or q <return> to quit---
ASTERISK-19 0x0000000000000000 in ?? ()


By: Andrew Parisio (parisioa) 2010-11-01 14:03:47

I tested against Neon .29.1 through .29.5, the previous post was .29.5

This is the output when compiled against neon .29.1, same end result:

#0  0x00007fdd755660b0 in strlen () from /lib/libc.so.6
#1  0x00007fdd75532ae0 in vfprintf () from /lib/libc.so.6
#2  0x00007fdd7555826a in vsnprintf () from /lib/libc.so.6
#3  0x00007fdd4bb13e29 in ne_vsnprintf (str=0x1038 <Address 0x1038 out of bounds>, size=140588434465401, fmt=0x40b8eb98 "8\020", ap=0x0) at ne_string.c:531
#4  0x00007fdd4bb137c7 in ne_set_error (sess=<value optimized out>, format=<value optimized out>) at ne_session.c:351
ASTERISK-1  0x00007fdd4bb1099d in aborted (req=<value optimized out>, doing=0x7fdd4bb223e7 "Could not read status line", code=<value optimized out>) at ne_request.c:208
ASTERISK-2  0x00007fdd4bb11abf in send_request (req=0x2538d30, request=<value optimized out>) at ne_request.c:875
ASTERISK-3  0x00007fdd4bb129b1 in ne_begin_request (req=0x2538d30) at ne_request.c:1168
ASTERISK-4  0x00007fdd4bb1ba25 in ne_xml_dispatch_request (req=0x2538d30, parser=0x253af50) at ne_xmlreq.c:87
ASTERISK-5  0x00007fdd4bb0ee38 in send_ews_request_and_parse (request=0x7fdd46439ed0, ctx=0x40b8ee60) at res_calendar_ews.c:528
ASTERISK-6 0x00007fdd4bb0f20e in ewscal_write_event (event=0x7fdd46485728) at res_calendar_ews.c:624
ASTERISK-7 0x00007fdd6da0e969 in calendar_write_exec (chan=0x2530788, cmd=0x40b8f160 "CALENDAR_WRITE", data=0x40b8f16f "testcalendar", value=0x40b8f3e3 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)")
   at res_calendar.c:1353
ASTERISK-8 0x0000000000504d8b in ast_func_write (chan=0x2530788, function=0x40b8f270 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)",
   value=0x40b8f3e3 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:3572
ASTERISK-9 0x000000000051920c in pbx_builtin_setvar_helper (chan=0x2530788, name=0x40b8f3a0 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)",
   value=0x40b8f3e3 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:9488
ASTERISK-10 0x0000000000519719 in pbx_builtin_setvar (chan=0x2530788, data=0x40b91700 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= \"My event\",\"mailto:andrewp@csgchannels.com\",228383580,228383640,1)") at pbx.c:9562
ASTERISK-11 0x00000000004fcb09 in pbx_exec (c=0x2530788, app=0x7fdd70058280, data=0x40b91700 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= \"My event\",\"mailto:andrewp@csgchannels.com\",228383580,228383640,1)")
   at pbx.c:1399
ASTERISK-12 0x00000000005066b0 in pbx_extension_helper (c=0x2530788, con=0x0, context=0x2530ce0 "from-staff", exten=0x2530d30 "1", priority=1, label=0x0, callerid=0x252e970 "1500", action=E_SPAWN, found=0x40b93ed0, combined_find_spawn=1)
   at pbx.c:4078
ASTERISK-13 0x000000000050806e in ast_spawn_extension (c=0x2530788, context=0x2530ce0 "from-staff", exten=0x2530d30 "1", priority=1, callerid=0x252e970 "1500", found=0x40b93ed0, combined_find_spawn=1) at pbx.c:4577
ASTERISK-14 0x0000000000508b15 in __ast_pbx_run (c=0x2530788, args=0x0) at pbx.c:4675
ASTERISK-15 0x000000000050a79d in pbx_thread (data=0x2530788) at pbx.c:4986
ASTERISK-16 0x000000000055ed0b in dummy_start (data=0x24dcfe0) at utils.c:971
ASTERISK-17 0x00007fdd74d75fc7 in start_thread () from /lib/libpthread.so.0
ASTERISK-18 0x00007fdd755ba64d in clone () from /lib/libc.so.6
ASTERISK-19 0x0000000000000000 in ?? ()


edit: stripped out my domain name. forgot to do that again.


By: Andrew Parisio (parisioa) 2010-11-01 16:21:58

I installed a clean debian box, neon .29.5, and 1.8.0.  Segfaults, but it doesn't say data optimized out now:


#0  0xb749f4f3 in strlen () from /lib/i686/cmov/libc.so.6
#1  0xb746c1e4 in vfprintf () from /lib/i686/cmov/libc.so.6
#2  0xb7490464 in vsnprintf () from /lib/i686/cmov/libc.so.6
#3  0xb6d0266a in ne_vsnprintf (
   str=0xd3c9e64 "Could not read status line: connection timed out",
   size=512, fmt=0xb6d11e82 "%s: %s", ap=0xb289a548 "ú\037Ѷ$\020")
   at ne_string.c:531
#4  0xb6d01fa8 in ne_set_error (sess=0xd3c9d90, format=0xb6d11e82 "%s: %s")
   at ne_session.c:353
ASTERISK-1  0xb6cfeaac in aborted (req=<value optimized out>,
   doing=0xb6d11ffa "Could not read status line", code=-1) at ne_request.c:208
ASTERISK-2  0xb6cffe76 in send_request (req=0xd510ea8, request=0xd510408)
   at ne_request.c:896
ASTERISK-3  0xb6d00fe0 in ne_begin_request (req=0xd510ea8) at ne_request.c:1189
ASTERISK-4  0xb6d0ad1d in ne_xml_dispatch_request (req=0xd510ea8, parser=0xd4fd990)
   at ne_xmlreq.c:87
ASTERISK-5  0xb6cfcca7 in send_ews_request_and_parse (request=0xd513888,
   ctx=0xb289a768) at res_calendar_ews.c:528
ASTERISK-6 0xb6cfd082 in ewscal_write_event (event=0xd513828)
   at res_calendar_ews.c:624
ASTERISK-7 0xb6fc39ca in calendar_write_exec (chan=0xd50d7c0,
   cmd=0xb289a920 "CALENDAR_WRITE", data=0xb289a92f "testcalendar",
   value=0xb289ab03 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580---Type <return> to continue, or q <return> to quit---
,228383640,1)") at res_calendar.c:1353
ASTERISK-8 0x0813cbf6 in ast_func_write (chan=0xd50d7c0,
   function=0xb289a9e0 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)",
   value=0xb289ab03 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:3572
ASTERISK-9 0x08150084 in pbx_builtin_setvar_helper (chan=0xd50d7c0,
   name=0xb289aac0 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)",
   value=0xb289ab03 " \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:9488
ASTERISK-10 0x08150572 in pbx_builtin_setvar (chan=0xd50d7c0,
   data=0xb289cd68 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:9562
ASTERISK-11 0x08135280 in pbx_exec (c=0xd50d7c0, app=0x9f74098,
   data=0xb289cd68 "CALENDAR_WRITE(testcalendar,summary,organizer,start,end,busystate)= \"My event\",\"mailto:andrewp@mydomain.com\",228383580,228383640,1)") at pbx.c:1399
ASTERISK-12 0x0813e380 in pbx_extension_helper (c=0xd50d7c0, con=0x0,
   context=0xd50db2c "from-staff", exten=0xd50db7c "1", priority=1,
   label=0x0, callerid=0xd4f8e50 "1500", action=E_SPAWN, found=0xb289f260,
   combined_find_spawn=1) at pbx.c:4078
---Type <return> to continue, or q <return> to quit---
ASTERISK-13 0x0813fc31 in ast_spawn_extension (c=0xd50d7c0,
   context=0xd50db2c "from-staff", exten=0xd50db7c "1", priority=1,
   callerid=0xd4f8e50 "1500", found=0xb289f260, combined_find_spawn=1)
   at pbx.c:4577
ASTERISK-14 0x081405c7 in __ast_pbx_run (c=0xd50d7c0, args=0x0) at pbx.c:4675
ASTERISK-15 0x0814204c in pbx_thread (data=0xd50d7c0) at pbx.c:4986
ASTERISK-16 0x081936df in dummy_start (data=0xd510418) at utils.c:971
ASTERISK-17 0xb72d94c0 in start_thread () from /lib/i686/cmov/libpthread.so.0
ASTERISK-18 0xb750984e in clone () from /lib/i686/cmov/libc.so.6
By: Leif Madsen (lmadsen) 2010-11-02 09:31:49

@pitel: Can I assign this issue to you? Would you like to take a look at it?
By: Leif Madsen (lmadsen) 2010-11-02 09:32:18

In the future please attach your backtraces as text files to the issue and not inline.
By: Bc. Jan Kaláb (pitel) 2010-11-02 16:27:28

Well, line 530 in res_calendar_ews.c (http://www.asterisk.org/doxygen/trunk/res__calendar__ews_8c-source.html) is just error message when libneon can't dispatch request to server. So I guess you misspelled your EWS address, or there is some network issue, or something like that...

Anyway, this error message is followed by some libneon cleanup code, which is probably trying to free something unallocated, which is causing this.

I hope I'll find time to fix this, but because of school, I can't promise that in near future. :(
By: Andrew Parisio (parisioa) 2010-11-02 16:41:02

I can use lynx and load the OWA & EWS pages directly from console of the asterisk server.  I also tried another working exchange server from another company entirely and had the same problem with it (that was an 07, my company uses a 2010).  

I'm not sure if this is a neon issue or a calendar_ews issue, but i'm guessing it's probably a neon issue which is why i tried compiling against every version of neon since the minimum supported build listed in the code (29.1).

I also built a clean debian machine, compiled neon on it, and then compiled 1.8.0 just to make sure my dev server wasn't causing any issues.  I have also compiled against trunk to make sure it wasn't fixed in later builds.
By: Andrew Parisio (parisioa) 2010-11-08 15:47:50.000-0600

I fixed an issue with the EWS implementation, then wrote a custom app and am able to access the calendar through the same stuff * should be using and it works just fine.  

I'm running the PHP + Soap call thing from the asterisk server so am confident that isn't the issue.
By: Andrew Parisio (parisioa) 2010-11-11 12:14:24.000-0600

So i started digging around in neon, and having commented out line 208 * no longer segfaults.  I ended up changing:

ne_set_error(sess, "%s: %s", doing ,ne_sock_error(sess->socket) );
to
ne_set_error(sess, "%s: On line 208", doing);

Now it cleanly errors out, but I still have no idea why the calendaring plugin doesn't work.  I'm running a contact directory out of EWS that is working fine and uses the exact same services.wsdl/exchange.asmx with NTLM authentication, running from the same host (but doesn't use neon).    

Now it spits this out instead of segfaulting:
[Nov 10 13:40:18] WARNING[22973]: res_calendar_ews.c:530 send_ews_request_and_parse: Unable to communicate with Exchange Web Service at 'https://mail.csgchannels.com/ews/services.wsdl': Could not read status line: On line 208

So it really to be an issue in neon causing the segfault.
By: Matt Jordan (mjordan) 2013-01-14 14:42:44.859-0600

I tend to agree with Andrew's analysis. Since this is a bug in the Neon library, I'm closing this out as not a bug (at least with Asterisk).