[CalendarServer-users] Connection aborted - took too long to close

[Andre LaBranche]

A couple things I forgot to add to the previous email:

* an example transaction wait log entry looks like this:
2015-02-06 11:28:15-0800 [-] [caldav-3]  [-] [txdav.common.datastore.sql#error] Transaction wait: PG-TXN<ultimatelyPerform: 28243 <SCHEDULE_ORGANIZER_SEND_WORK>>, Statements: 745, IUDs: 724, Statement: select WORK_ID, JOB_ID, ICALENDAR_UID, WORK_TYPE from SCHEDULE_WORK where ICALENDAR_UID = %s and WORK_ID != %s order by WORK_ID asc limit %s

* If you set the Statistics sub-key to true, every DB transaction will be logged to a separate sqlstats.log file adjacent to error.log. This might be useful if you really want to see everything happening in the DB.

-dre

> On Feb 6, 2015, at 11:28 AM, Andre LaBranche <dre at apple.com> wrote:
> 
>> 
>> On Feb 5, 2015, at 7:58 PM, Jacques Distler <distler at golem.ph.utexas.edu> wrote:
>> 
>> 
>>> On Feb 5, 2015, at 8:28 PM, Andre LaBranche <dre at apple.com> wrote:
>>> 
>>> To enable 'accounting' logs for Calendar Server, edit caldavd.plist to add target principals whose activity should be logged, e.g.:
>>> 
>>>   <!-- Enable accounting for certain operations -->
>>>   <key>AccountingCategories</key>
>>>   <dict>
>>>     <key>iTIP</key>
>>>     <false/>
>>>     <key>HTTP</key>
>>>     <true/>
>>>   </dict>
>>> 
>>>   <!-- Enable accounting for specific principals -->
>>>   <key>AccountingPrincipals</key>
>>>   <array>
>>>     <string>/principals/__uids__/454D85C0-09F0-4DC6-A3C6-97DFEB4622CD/</string>
>>>   </array>
>>> 
>>> Once the change is made, HUP the master process or restart the service. The logs are written to an 'accounting' directory adjacent to the other logs.
>> 
>> OK, so I did that, and I now have a directory full of text files containing request/response pairs. But they all look like they completed successfully.
>> 
>> Does the server not log ABORTED responses (which, after all, is what we are talking about here)?
> 
> Hi,
> 
> I don't think we log things we cannot send back to the client, just that the connection was aborted.
> 
> In general, this log message means one of two things:
> 
> 1) We successfully wrote all response data to the client and called socket.close() and that took more than 20 secs to complete
> 
> 2) We timed out the connection because the response took more than 5 mins to generate and when trying to call socket.close() that timed out after 20 secs
> 
> Based on your original description, I'm leaning towards #2. We can try enabling some database logging to see what's happening and how long it's taking. In caldavd.plist, create a LogDatabase dict that looks like this:
> 
>    <key>LogDatabase</key>
>    <dict>
>        <key>TransactionWaitSeconds</key>
>        <integer>30</integer>
>        <key>Statistics</key>
>        <false/>
>    </dict>
> 
> Then HUP or bounce the service. You should now see entries in error.log whenever a running database transaction lasts longer than 30 seconds. If you can link those entries to the requests from your clients with large calendars, that strongly suggests that these requests are now taking long enough that the client gives up.
> 
> While there is a server-side timeout, the client's timeout (if you're using Apple clients) is less than our default, so adjusting our timeout will likely not help.
> 
> Once we can identify what types of transactions are taking too long, maybe we can offer some advice on how to proceed.
> 
> -dre
> _______________________________________________
> calendarserver-users mailing list
> calendarserver-users at lists.macosforge.org <mailto:calendarserver-users at lists.macosforge.org>
> https://lists.macosforge.org/mailman/listinfo/calendarserver-users <https://lists.macosforge.org/mailman/listinfo/calendarserver-users>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.macosforge.org/pipermail/calendarserver-users/attachments/20150206/23412346/attachment-0001.html>