Q: Calendar Server Reported Error: Operation CalDAVAccountRefreshQueueableOperation

How does the contents of

/var/pgsql.pre-restore-2011-10-12_22:56:38_CEST compare with /var/pgsql? Are there a lot more base/*, global/* files present with large sizes in the "pre-restore" one?

server01:caldavd root# cd /var/pgsql.pre-restore-2011-10-12_22:56:38_CEST

server01:pgsql.pre-restore-2011-10-12_22:56:38_CEST root# ls -al

total 72

drwx------  17 _postgres  _postgres    578 Oct 12 22:56 .

drwxr-xr-x  42 root       wheel       1428 Oct 12 22:56 ..

-rw-------   1 _postgres  _postgres      4 Sep 30 20:10 PG_VERSION

drwx------   9 _postgres  _postgres    306 Sep 30 20:10 base

// 7 base/* directories (see below)

drwx------  43 _postgres  _postgres   1462 Oct 12 22:56 global

// 41 base/* files

drwx------   3 _postgres  _postgres    102 Sep 30 20:10 pg_clog

-rw-------   1 _postgres  _postgres   3939 Sep 30 20:10 pg_hba.conf

-rw-------   1 _postgres  _postgres   1636 Sep 30 20:10 pg_ident.conf

drwx------   4 _postgres  _postgres    136 Sep 30 20:10 pg_multixact

drwx------   3 _postgres  _postgres    102 Oct 12 22:56 pg_notify

drwx------   2 _postgres  _postgres     68 Oct 12 22:56 pg_stat_tmp

drwx------   3 _postgres  _postgres    102 Sep 30 20:10 pg_subtrans

drwx------   2 _postgres  _postgres     68 Sep 30 20:10 pg_tblspc

drwx------   2 _postgres  _postgres     68 Sep 30 20:10 pg_twophase

drwx------   5 _postgres  _postgres    170 Oct 12 16:56 pg_xlog

-rw-------   1 _postgres  _postgres  17935 Sep 30 20:10 postgresql.conf

-rw-------   1 _postgres  _postgres    385 Oct 12 22:56 postmaster.opts

server01:var root# cd /var/pgsql

server01:pgsql root# ls -al

total 80

drwx------  18 _postgres  _postgres    612 Oct 20 22:12 .

drwxr-xr-x  42 root       wheel       1428 Oct 12 22:56 ..

-rw-------   1 _postgres  _postgres      4 Oct 12 22:56 PG_VERSION

drwx------   5 _postgres  _postgres    170 Oct 12 22:57 base

// 3 base/* directories (see below)

drwx------  42 _postgres  _postgres   1428 Oct 20 22:13 global

// 40 base/* files

drwx------   3 _postgres  _postgres    102 Oct 12 22:56 pg_clog

-rw-------   1 _postgres  _postgres   3939 Oct 12 22:56 pg_hba.conf

-rw-------   1 _postgres  _postgres   1636 Oct 12 22:56 pg_ident.conf

drwx------   4 _postgres  _postgres    136 Oct 12 22:56 pg_multixact

drwx------   3 _postgres  _postgres    102 Oct 20 22:12 pg_notify

drwx------   3 _postgres  _postgres    102 Oct 21 22:35 pg_stat_tmp

drwx------   3 _postgres  _postgres    102 Oct 12 22:56 pg_subtrans

drwx------   2 _postgres  _postgres     68 Oct 12 22:56 pg_tblspc

drwx------   2 _postgres  _postgres     68 Oct 12 22:56 pg_twophase

drwx------   4 _postgres  _postgres    136 Oct 12 22:56 pg_xlog

-rw-------   1 _postgres  _postgres  17935 Oct 12 22:56 postgresql.conf

-rw-------   1 _postgres  _postgres    385 Oct 20 22:12 postmaster.opts

-rw-------   1 _postgres  _postgres     37 Oct 20 22:12 postmaster.pid

server01:pgsql.pre-restore-2011-10-12_22:56:38_CEST root# cd /var/pgsql.pre-restore-2011-10-12_22:56:38_CEST/base/

server01:base root# ls -al

total 0

drwx------    9 _postgres  _postgres    306 Sep 30 20:10 .

drwx------   17 _postgres  _postgres    578 Oct 12 22:56 ..

drwx------  213 _postgres  _postgres   7242 Oct 12 22:47 1

drwx------  213 _postgres  _postgres   7242 Sep 30 20:10 11866

drwx------  213 _postgres  _postgres   7242 Oct 12 22:47 11874

drwx------  341 _postgres  _postgres  11594 Oct 12 22:56 16388

drwx------  357 _postgres  _postgres  12138 Oct 12 22:56 16389

drwx------  495 _postgres  _postgres  16830 Oct 12 22:56 16390

drwx------  259 _postgres  _postgres   8806 Oct 12 22:48 16391

server01:base root# cd /var/pgsql/base/

server01:base root# ls -al

total 0

drwx------    5 _postgres  _postgres   170 Oct 12 22:57 .

drwx------   18 _postgres  _postgres   612 Oct 20 22:12 ..

drwx------  214 _postgres  _postgres  7276 Oct 20 22:13 1

drwx------  213 _postgres  _postgres  7242 Oct 12 22:57 11866

drwx------  214 _postgres  _postgres  7276 Oct 20 22:12 11874

Message was edited by: mappler

I'm experiencing the same problem. iCal Server on my Lion Server was working well, but since some weeks (I guess) it isn't functioning well.

One of the symptoms is the error 500 on the CalDAVAccountRefreshQueueableOperation operation in iCal on Mac (after some minutes of trying to sync).

When I browse to https://<domain of server>/webcal/ - which normally works -, I get the following Apache error:

Proxy Error

 

The proxy server could not handle the request GET /webcal.

Reason: Error during SSL Handshake with remote server

 

Apache/2.2.20 (Unix) mod_ssl/2.2.20 OpenSSL/0.9.8r DAV/2 PHP/5.3.6 with Suhosin-Patch Server at <domain of server> Port 443

I've tried some things and it appears that when I restart the iCal Server (by disabling and enabling it in Server.app) it works well for some time. Later it stops working again.

An interesting thing is that I'm experiencing the same kind of problems with the Address Book Server on the same Mac. Address Book on a client Mac doesn't sync, although it doesn't show an error. After restarting the Address Book Server, it works again for some time, just like the iCal Server.

To the other ones who experience this issue: does restarting the iCal Server work for you? In case of no: I always restart the iCal and Address Book Server at the same time (first disabling both, then enabling both), maybe that makes a difference?

Screenshots: iCal error, Apache error webcal.

Should I report these things to Apple, or are they reading this tread as well?

I wish I had kept a copy of the error that I had received on an OS X client with iCal after updating Lion Server to 10.7.2.  I think it may have been the same.  In any case, I fixed whatever my error was by disabling access to Calendar using Edit Access to Services for specific users (User Pane in Server.app), applying, and and then reenabling access.  A shot in the dark... apologies if this only makes the ordeal more frustrating.

Ryan

Ryan, are you sure that the user data in the calendars will remain on the server when the access is disabled? I'm pretty scared to try it out, to be honoust with you …

Jonathan,

I had the same great fear.  But I went with it. Thankfully I lost no data. So chances are it won't cause problems for others but I cannot be certain. 

Ryan

Based on your PostgreSQL log something funny happened as 2011-10-12 22:56 - after that the caldav database (and others) appear to be missing. You might want to try this:

(Shut down all services first)

sudo serveradmin stop postgres

sudo mv /var/pgsql /var/pgsql.broken

suco cp -r /var/pgsql.pre-restore-2011-10-12_22:56:38_CEST /var/pgsql

sudo serveradmin start postgres

sudo -u _postgres psql -U caldav caldav

The last command will hopefully show a working postgres shell prompt and not an error. If it does startup the calendar service and monitor the /var/log/caldavd/error.log - again hopefully no errors. Try connecting with a calendar client and see if previous data is present.

(Shut down all services first)

done.

sudo serveradmin stop postgres

done.

sudo mv /var/pgsql /var/pgsql.broken

done.

sudo cp -r /var/pgsql.pre-restore-2011-10-12_22:56:38_CEST /var/pgsql

done.

sudo serveradmin start postgres

done: postgres:error = "CANNOT_START_SERVICE_TIMEOUT_ERR"

UPDATE: I had to update the access rights (hopefully that is correct):

chown -R _postgres:_postgres pgsql

done.

sudo -u _postgres psql -U caldav caldav

NEXT ERROR: psql: FATAL: role "caldav" does not exist

Message was edited by: mappler

My system.log shows the same errors like in my post from 20.10.2011 12:33.

When I try to go online with iCal, I still get the

The server responded with

“500”

to operation CalDAVAccountRefreshQueueableOperation.

but I also noticed in the apache error log that the following is listed every time I try to go online with iCal (happens about 12 times a second):

[Tue Oct 25 07:00:42 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3326 (127.0.0.1) failed

[Tue Oct 25 07:00:42 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:31:15 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3326 (127.0.0.1) failed

[Tue Oct 25 07:31:15 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:31:15 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3328 (127.0.0.1) failed

[Tue Oct 25 07:31:15 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:31:15 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3325 (127.0.0.1) failed

[Tue Oct 25 07:31:15 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:31:15 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3327 (127.0.0.1) failed

[Tue Oct 25 07:31:15 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:31:15 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3324 (127.0.0.1) failed

[Tue Oct 25 07:31:15 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:31:15 2011] [error] (61)Connection refused: proxy: HTTP: attempt to connect to 127.0.0.1:3329 (127.0.0.1) failed

...and then about every minute or so I get the following that repeats over and over:

[Tue Oct 25 07:31:15 2011] [error] ap_proxy_connect_backend disabling worker for (127.0.0.1)

[Tue Oct 25 07:37:31 2011] [notice] caught SIGTERM, shutting down

[Tue Oct 25 07:37:32 2011] [notice] Apache/2.2.20 (Unix) mod_ssl/2.2.20 OpenSSL/0.9.8r DAV/2 PHP/5.3.6 with Suhosin-Patch configured -- resuming normal operations

[Tue Oct 25 07:37:35 2011] [notice] caught SIGTERM, shutting down

Does this point to anything that I could try?

OK, so remove the current /var/pgsql and replace with a copy of /var/pgsql.pre-restore-2011-09-30_20:10:02_CEST, which is one backup back.

no chance.

Neither with July-Backup.

But the iCal-Server was always OK before the 10.7.2-Update.

Message was edited by: mappler

OK, after some minutes, suddenly, iCal-Server is working again.

It is running with my July Backup.

Hopefully, I can restore the one from September or October afterwards...