Re: [Davical-general] Failures upgrading ubuntu 15.10 -> 16.04 php7 ?

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Ok, so I still get these '500’ server errors when invoking  'CalDAVAccountRefreshQueueableOperation’ in iCal, and no responses in other clients.
I’ve tracked it down that it has to be a php7 or apache config thing, as I only see responses in the debug log when I type in a caldav url in a browser doing a GET request for a calendar.
So my question is: Why don’t I get responses to PROPFIND or other requests?

So I tried this again, this time with full debug logging:

[Mon Apr 25 17:00:18.697045 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: ALL: I18N:Set locale to =nl_NL.UTF-8=
[Mon Apr 25 17:00:18.697240 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: ALL: I18N:Bound domain =davical= to location =../locale= using character set =UTF-8=
[Mon Apr 25 17:00:18.697365 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: ALL: caldav:Version (1.1.4) == 1001.4
[Mon Apr 25 17:00:18.697772 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: always: Query: DBGQ: SELECT schema_major, schema_minor, schema_patch FROM awl_db_revision ORDER BY schema_id DESC LIMIT 1;
[Mon Apr 25 17:00:18.711231 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: always: Query: DBGQ: Took: 0,003685 to find 1 rows.
[Mon Apr 25 17:00:18.711816 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: always: Query: DBGQ: SET TIMEZONE TO ?
[Mon Apr 25 17:00:18.711984 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: always: Query: DBGQ:  "0" => "UTC"
[Mon Apr 25 17:00:18.713420 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: always: Query: DBGQ: Took: 0,001189 to find 0 rows.
[Mon Apr 25 17:00:18.714164 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: :***************** Request Header ****************
[Mon Apr 25 17:00:18.714282 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: :PROPFIND /cal/caldav.php/test/calendar/
[Mon Apr 25 17:00:18.714350 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Host: bla.foo.bar
[Mon Apr 25 17:00:18.714710 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Content-Type: text/xml
[Mon Apr 25 17:00:18.714913 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Depth: 0
[Mon Apr 25 17:00:18.714994 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Brief: t
[Mon Apr 25 17:00:18.715066 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Accept: */*
[Mon Apr 25 17:00:18.715134 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Connection: keep-alive
[Mon Apr 25 17:00:18.715203 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Prefer: return-minimal
[Mon Apr 25 17:00:18.715272 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->User-Agent: Mac_OS_X/10.9.5 (13F1712) CalendarAgent/176.2
[Mon Apr 25 17:00:18.715340 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Content-Length: 743
[Mon Apr 25 17:00:18.715410 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Accept-Language: nl-nl
[Mon Apr 25 17:00:18.715476 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: headers:-->Accept-Encoding: gzip, deflate
[Mon Apr 25 17:00:18.715542 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: :******************** Request ********************
[Mon Apr 25 17:00:18.715647 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:--><?xml version="1.0" encoding="UTF-8"?>
[Mon Apr 25 17:00:18.715721 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:--><A:propfind xmlns:A="DAV:">
[Mon Apr 25 17:00:18.715789 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->  <A:prop>
[Mon Apr 25 17:00:18.715853 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <B:calendar-home-set xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.715921 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <B:calendar-user-address-set xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.716049 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <A:current-user-principal/>
[Mon Apr 25 17:00:18.716115 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <A:displayname/>
[Mon Apr 25 17:00:18.716178 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <C:dropbox-home-URL xmlns:C="http://calendarserver.org/ns/"/>
[Mon Apr 25 17:00:18.716241 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <C:email-address-set xmlns:C="http://calendarserver.org/ns/"/>
[Mon Apr 25 17:00:18.716306 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <C:notification-URL xmlns:C="http://calendarserver.org/ns/"/>
[Mon Apr 25 17:00:18.716371 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <A:principal-collection-set/>
[Mon Apr 25 17:00:18.716431 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <A:principal-URL/>
[Mon Apr 25 17:00:18.716597 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <A:resource-id/>
[Mon Apr 25 17:00:18.716676 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <B:schedule-inbox-URL xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.716741 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <B:schedule-outbox-URL xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.716806 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->    <A:supported-report-set/>
[Mon Apr 25 17:00:18.716868 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->  </A:prop>
[Mon Apr 25 17:00:18.716934 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:--></A:propfind>
[Mon Apr 25 17:00:18.716997 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: LOG: request:-->
[Mon Apr 25 17:00:18.717166 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: ALL: HTTPAuth::AuthFailedResponse Requesting authentication in the 'bla CalDAV Store' realm
[Mon Apr 25 17:00:18.717298 2016] [:error] [pid 10820] [client 192.168.0.1:54524] davical: ALL: HTTPAuth::Session: User is not authorised: 192.168.0.1 
[Mon Apr 25 17:00:18.851119 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: I18N:Set locale to =nl_NL.UTF-8=
[Mon Apr 25 17:00:18.851300 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: I18N:Bound domain =davical= to location =../locale= using character set =UTF-8=
[Mon Apr 25 17:00:18.851415 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: caldav:Version (1.1.4) == 1001.4
[Mon Apr 25 17:00:18.851687 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: always: Query: DBGQ: SELECT schema_major, schema_minor, schema_patch FROM awl_db_revision ORDER BY schema_id DESC LIMIT 1;
[Mon Apr 25 17:00:18.864895 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: always: Query: DBGQ: Took: 0,003775 to find 1 rows.
[Mon Apr 25 17:00:18.865461 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: always: Query: DBGQ: SET TIMEZONE TO ?
[Mon Apr 25 17:00:18.865595 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: always: Query: DBGQ:  "0" => "UTC"
[Mon Apr 25 17:00:18.867140 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: always: Query: DBGQ: Took: 0,001321 to find 0 rows.
[Mon Apr 25 17:00:18.867736 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: :***************** Request Header ****************
[Mon Apr 25 17:00:18.867854 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: :PROPFIND /cal/caldav.php/test/calendar/
[Mon Apr 25 17:00:18.867918 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Host: bla.foo.bar
[Mon Apr 25 17:00:18.868028 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Accept: */*
[Mon Apr 25 17:00:18.868093 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Brief: t
[Mon Apr 25 17:00:18.868167 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Authorization: Delicious tasty password eaten by debugging monster!
[Mon Apr 25 17:00:18.868243 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Accept-Language: nl-nl
[Mon Apr 25 17:00:18.868311 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Accept-Encoding: gzip, deflate
[Mon Apr 25 17:00:18.868385 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Content-Type: text/xml
[Mon Apr 25 17:00:18.868461 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Content-Length: 743
[Mon Apr 25 17:00:18.868533 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Depth: 0
[Mon Apr 25 17:00:18.868604 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Connection: keep-alive
[Mon Apr 25 17:00:18.868676 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->User-Agent: Mac_OS_X/10.9.5 (13F1712) CalendarAgent/176.2
[Mon Apr 25 17:00:18.868750 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: headers:-->Prefer: return-minimal
[Mon Apr 25 17:00:18.868818 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: :******************** Request ********************
[Mon Apr 25 17:00:18.868929 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:--><?xml version="1.0" encoding="UTF-8"?>
[Mon Apr 25 17:00:18.869009 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:--><A:propfind xmlns:A="DAV:">
[Mon Apr 25 17:00:18.869077 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->  <A:prop>
[Mon Apr 25 17:00:18.869147 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <B:calendar-home-set xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.869222 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <B:calendar-user-address-set xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.869293 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <A:current-user-principal/>
[Mon Apr 25 17:00:18.869365 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <A:displayname/>
[Mon Apr 25 17:00:18.869437 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <C:dropbox-home-URL xmlns:C="http://calendarserver.org/ns/"/>
[Mon Apr 25 17:00:18.869501 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <C:email-address-set xmlns:C="http://calendarserver.org/ns/"/>
[Mon Apr 25 17:00:18.869561 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <C:notification-URL xmlns:C="http://calendarserver.org/ns/"/>
[Mon Apr 25 17:00:18.869630 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <A:principal-collection-set/>
[Mon Apr 25 17:00:18.869705 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <A:principal-URL/>
[Mon Apr 25 17:00:18.869777 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <A:resource-id/>
[Mon Apr 25 17:00:18.869849 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <B:schedule-inbox-URL xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.869922 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <B:schedule-outbox-URL xmlns:B="urn:ietf:params:xml:ns:caldav"/>
[Mon Apr 25 17:00:18.869993 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->    <A:supported-report-set/>
[Mon Apr 25 17:00:18.870110 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->  </A:prop>
[Mon Apr 25 17:00:18.870184 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:--></A:propfind>
[Mon Apr 25 17:00:18.870253 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: request:-->
[Mon Apr 25 17:00:18.870528 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: Cache:Using NoCache dummy interface
[Mon Apr 25 17:00:18.870744 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ: SELECT *, 0::BIT(24) AS privileges FROM dav_principal WHERE lower(username)=lower(text(:param))
[Mon Apr 25 17:00:18.870866 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":param" => "test"
[Mon Apr 25 17:00:18.880880 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ: Took: 0,009780 to find 1 rows.
[Mon Apr 25 17:00:18.881685 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: BasicAuth: Query: DBGQ: SELECT role_name FROM role_member m join roles r ON r.role_no = m.role_no WHERE user_no = :user_no 
[Mon Apr 25 17:00:18.881826 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: BasicAuth: Query: DBGQ:  ":user_no" => "1007"
[Mon Apr 25 17:00:18.884669 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: BasicAuth: Query: DBGQ: Took: 0,002616 to find 0 rows.
[Mon Apr 25 17:00:18.885438 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: Principal:Path split into at least /// test /// calendar /// 
[Mon Apr 25 17:00:18.885712 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ: SELECT *, pprivs(:session_principal::int8,principal_id,:scan_depth::int) AS privileges FROM dav_principal WHERE lower(username)=lower(text(:param))
[Mon Apr 25 17:00:18.885849 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":session_principal" => "6394"
[Mon Apr 25 17:00:18.885950 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":scan_depth" => "2"
[Mon Apr 25 17:00:18.886047 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":param" => "test"
[Mon Apr 25 17:00:18.893312 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ: Took: 0,006948 to find 1 rows.
[Mon Apr 25 17:00:18.894007 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: caldav: Query: DBGQ: SELECT * FROM collection WHERE dav_name = :exact_name ORDER BY LENGTH(dav_name) DESC LIMIT 1
[Mon Apr 25 17:00:18.894137 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: caldav: Query: DBGQ:  ":exact_name" => "/test/calendar/"
[Mon Apr 25 17:00:18.897982 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: caldav: Query: DBGQ: Took: 0,003630 to find 1 rows.
[Mon Apr 25 17:00:18.898202 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: caldav: Collection '/test/calendar/' is 6395, type calendar
[Mon Apr 25 17:00:18.898340 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: Principal:Path split into at least /// test /// calendar /// 
[Mon Apr 25 17:00:18.898698 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ: SELECT *, pprivs(:session_principal::int8,principal_id,:scan_depth::int) AS privileges FROM dav_principal WHERE lower(username)=lower(text(:param))
[Mon Apr 25 17:00:18.898859 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":session_principal" => "6394"
[Mon Apr 25 17:00:18.898966 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":scan_depth" => "2"
[Mon Apr 25 17:00:18.899066 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ:  ":param" => "test"
[Mon Apr 25 17:00:18.902278 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: Principal: Query: DBGQ: Took: 0,002899 to find 1 rows.
[Mon Apr 25 17:00:18.903119 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: DAVPrincipal: Query: DBGQ: SELECT usr.username FROM group_member JOIN principal ON (principal_id=group_id) JOIN usr USING(user_no) WHERE usr.active=true AND member_id = :member_id UNION SELECT usr.username FROM group_member LEFT JOIN grants ON (to_principal=group_id)
[Mon Apr 25 17:00:18.903245 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: DAVPrincipal: Query: DBGQ:  JOIN principal ON (principal_id=by_principal) JOIN usr USING(user_no) WHERE usr.active=true AND member_id = :member_id and by_principal != member_id ORDER BY 1
[Mon Apr 25 17:00:18.903336 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: DAVPrincipal: Query: DBGQ:  ":member_id" => "6394"
[Mon Apr 25 17:00:18.912907 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: LOG: DAVPrincipal: Query: DBGQ: Took: 0,009329 to find 0 rows.
[Mon Apr 25 17:00:18.913051 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: principal: User: test (1007) URL: /cal/caldav.php/test/, By Email: 0
[Mon Apr 25 17:00:18.913547 2016] [:error] [pid 10872] [client 192.168.0.1:54525] davical: ALL: caldav:Full permissions for user accessing their own hierarchy
[Mon Apr 25 17:00:19.035250 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: I18N:Set locale to =nl_NL.UTF-8=
[Mon Apr 25 17:00:19.035441 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: I18N:Bound domain =davical= to location =../locale= using character set =UTF-8=
[Mon Apr 25 17:00:19.035558 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: caldav:Version (1.1.4) == 1001.4
[Mon Apr 25 17:00:19.035902 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: always: Query: DBGQ: SELECT schema_major, schema_minor, schema_patch FROM awl_db_revision ORDER BY schema_id DESC LIMIT 1;
[Mon Apr 25 17:00:19.048977 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: always: Query: DBGQ: Took: 0,003744 to find 1 rows.
[Mon Apr 25 17:00:19.049762 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: always: Query: DBGQ: SET TIMEZONE TO ?
[Mon Apr 25 17:00:19.049895 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: always: Query: DBGQ:  "0" => "UTC"
[Mon Apr 25 17:00:19.051412 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: always: Query: DBGQ: Took: 0,001303 to find 0 rows.
[Mon Apr 25 17:00:19.051990 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: :***************** Request Header ****************
[Mon Apr 25 17:00:19.052115 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: :PROPFIND /cal/caldav.php/test/calendar/
[Mon Apr 25 17:00:19.052180 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Host: bla.foo.bar
[Mon Apr 25 17:00:19.052252 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Accept: */*
[Mon Apr 25 17:00:19.052315 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Brief: t
[Mon Apr 25 17:00:19.052393 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Authorization: Delicious tasty password eaten by debugging monster!
[Mon Apr 25 17:00:19.052469 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Accept-Language: nl-nl
[Mon Apr 25 17:00:19.052543 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Accept-Encoding: gzip, deflate
[Mon Apr 25 17:00:19.052618 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Content-Type: text/xml
[Mon Apr 25 17:00:19.052692 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Content-Length: 170
[Mon Apr 25 17:00:19.052764 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Depth: 0
[Mon Apr 25 17:00:19.052837 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Connection: keep-alive
[Mon Apr 25 17:00:19.052968 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->User-Agent: Mac_OS_X/10.9.5 (13F1712) CalendarAgent/176.2
[Mon Apr 25 17:00:19.053042 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: headers:-->Prefer: return-minimal
[Mon Apr 25 17:00:19.053116 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: :******************** Request ********************
[Mon Apr 25 17:00:19.053215 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:--><?xml version="1.0" encoding="UTF-8"?>
[Mon Apr 25 17:00:19.053295 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:--><A:propfind xmlns:A="DAV:">
[Mon Apr 25 17:00:19.053370 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:-->  <A:prop>
[Mon Apr 25 17:00:19.053429 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:-->    <A:current-user-principal/>
[Mon Apr 25 17:00:19.053490 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:-->    <A:principal-collection-set/>
[Mon Apr 25 17:00:19.053565 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:-->  </A:prop>
[Mon Apr 25 17:00:19.053638 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:--></A:propfind>
[Mon Apr 25 17:00:19.053703 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: request:-->
[Mon Apr 25 17:00:19.053873 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: Cache:Using NoCache dummy interface
[Mon Apr 25 17:00:19.054056 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ: SELECT *, 0::BIT(24) AS privileges FROM dav_principal WHERE lower(username)=lower(text(:param))
[Mon Apr 25 17:00:19.054174 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":param" => "test"
[Mon Apr 25 17:00:19.064259 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ: Took: 0,009842 to find 1 rows.
[Mon Apr 25 17:00:19.065063 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: BasicAuth: Query: DBGQ: SELECT role_name FROM role_member m join roles r ON r.role_no = m.role_no WHERE user_no = :user_no 
[Mon Apr 25 17:00:19.065209 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: BasicAuth: Query: DBGQ:  ":user_no" => "1007"
[Mon Apr 25 17:00:19.068012 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: BasicAuth: Query: DBGQ: Took: 0,002565 to find 0 rows.
[Mon Apr 25 17:00:19.068725 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: Principal:Path split into at least /// test /// calendar /// 
[Mon Apr 25 17:00:19.069004 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ: SELECT *, pprivs(:session_principal::int8,principal_id,:scan_depth::int) AS privileges FROM dav_principal WHERE lower(username)=lower(text(:param))
[Mon Apr 25 17:00:19.069142 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":session_principal" => "6394"
[Mon Apr 25 17:00:19.069241 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":scan_depth" => "2"
[Mon Apr 25 17:00:19.069339 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":param" => "test"
[Mon Apr 25 17:00:19.076562 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ: Took: 0,006915 to find 1 rows.
[Mon Apr 25 17:00:19.077251 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: caldav: Query: DBGQ: SELECT * FROM collection WHERE dav_name = :exact_name ORDER BY LENGTH(dav_name) DESC LIMIT 1
[Mon Apr 25 17:00:19.077384 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: caldav: Query: DBGQ:  ":exact_name" => "/test/calendar/"
[Mon Apr 25 17:00:19.081189 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: caldav: Query: DBGQ: Took: 0,003595 to find 1 rows.
[Mon Apr 25 17:00:19.081462 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: caldav: Collection '/test/calendar/' is 6395, type calendar
[Mon Apr 25 17:00:19.081605 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: Principal:Path split into at least /// test /// calendar /// 
[Mon Apr 25 17:00:19.081855 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ: SELECT *, pprivs(:session_principal::int8,principal_id,:scan_depth::int) AS privileges FROM dav_principal WHERE lower(username)=lower(text(:param))
[Mon Apr 25 17:00:19.081998 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":session_principal" => "6394"
[Mon Apr 25 17:00:19.082101 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":scan_depth" => "2"
[Mon Apr 25 17:00:19.082200 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ:  ":param" => "test"
[Mon Apr 25 17:00:19.085530 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: Principal: Query: DBGQ: Took: 0,002912 to find 1 rows.
[Mon Apr 25 17:00:19.086256 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: DAVPrincipal: Query: DBGQ: SELECT usr.username FROM group_member JOIN principal ON (principal_id=group_id) JOIN usr USING(user_no) WHERE usr.active=true AND member_id = :member_id UNION SELECT usr.username FROM group_member LEFT JOIN grants ON (to_principal=group_id)
[Mon Apr 25 17:00:19.086374 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: DAVPrincipal: Query: DBGQ:  JOIN principal ON (principal_id=by_principal) JOIN usr USING(user_no) WHERE usr.active=true AND member_id = :member_id and by_principal != member_id ORDER BY 1
[Mon Apr 25 17:00:19.086562 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: DAVPrincipal: Query: DBGQ:  ":member_id" => "6394"
[Mon Apr 25 17:00:19.096117 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: LOG: DAVPrincipal: Query: DBGQ: Took: 0,009290 to find 0 rows.
[Mon Apr 25 17:00:19.096260 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: principal: User: test (1007) URL: /cal/caldav.php/test/, By Email: 0
[Mon Apr 25 17:00:19.096761 2016] [:error] [pid 11498] [client 192.168.0.1:54526] davical: ALL: caldav:Full permissions for user accessing their own hierarchy

And there the logging stops. No response.
Any idea where I should start searching?

Op 24 apr. 2016, om 23:49 heeft Antoin Verschuren <da...@an...> het volgende geschreven:

> Hi all,
> 
> This is my first message to this list.
> I’m not a postgresql or php expert, but I do know my way around.
> 
> I have recently upgraded my ubuntu server from 15.10 to 16.04, and everything works, except davical ;-(.
> 
> Since I’ve upgraded, my clients get errors, don’t connect, or don’t update.
> I first thought it was the davical database, since it had problems with the update-davical-database script.
> It had multiple version entires in the awl_db_revision table,  but SELECT check_db_revision(1,2,11); failed anyway, saying the Database has not been upgraded to 1.2.11.
> I fixed that, but didn’t help.
> 
> So I created a brand new DB with new users with the create-database.sh script running as postgres, and tested again, but still the same errors on the clients.
> I restored a dump from my current database from 2 months ago, and still the same errors.
> I can access my DB and users with the davical administration webinterface, so the DB looks ok, but clients fail.
> Most android clients (davdroid, caldav-sync) don’t give errors, but fail to update.
> All my IOS/OSX clients give me this error: '500' 'CalDAVAccountRefreshQueueableOperation'.
> 
> I was wondering if the upgrade from php5.6 to 7.0 had anything to do with it.
> PHP5.6 is no longer in ubuntu 16:04, so mod_php5 is disabled in apache2, and mod_php7.0 is enabled.
> 
> 
> ------------------------------------------------------------------------------
> Find and fix application performance issues faster with Applications Manager
> Applications Manager provides deep performance insights into multiple tiers of
> your business applications. It resolves application problems quickly and
> reduces your MTTR. Get your free trial!
> https://ad.doubleclick.net/ddm/clk/302982198;130105516;z
> _______________________________________________
> Davical-general mailing list
> Dav...@li...
> https://lists.sourceforge.net/lists/listinfo/davical-general