Lion Server push notifications to iOS 5 only partially working

What do you see in the "push-transports" section on that /calendars/users/myuser/ page? And is calendarserver_monitor_notifications working for you? That command helps determine that XMPP is working, which is important because APNS notifications are "bridged" from XMPP. So without XMPP working, APNS definitely won't either.

There is no "push-transports" section on that page I am afraid. XMPP is certainly troubled, since the message is as follows (after typing my password):

Error: Unable to determine xmpp server name

I have the ichat server running though and it works fine.

Ok, so let's get XMPP working...

Do you see any messages in /var/log/caldavd/error.log that refer to XMPP or notification issues?

When calendar server is running, do you see any jabberd_notification processes? (in Terminal run "ps aux | grep jabberd_notification")

What do you see when you run "sudo serveradmin settings calendar:Notifications" in Terminal when calendar server is running? (Please delete any identfying hostnames and passwords from that output before pasting here)

What do you see when you run "sudo serveradmin settings notification:jabberdClientPortTLS" in Terminal when calendar server is running?

In /var/log/caldavd/error.log I see

XmlStream,client] [twistedcaldav.notify.XMPPNotifier#error] PubSub node configuration error: <error code='403' type='auth'><forbidden xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error>

I see the following processes:

_jabber 183 0,0 0,1 2471888 5992 ?? S 6:38pm 0:02.33 /usr/libexec/jabberd/s2s -c /etc/jabberd_notification/s2s.xml

_jabber 182 0,0 0,1 2471860 6356 ?? S 6:38pm 0:02.40 /usr/libexec/jabberd/c2s -c /etc/jabberd_notification/c2s.xml

_jabber 181 0,0 0,1 2437448 5304 ?? S 6:38pm 0:00.44 /usr/libexec/jabberd/router -c /etc/jabberd_notification/router.xml

_jabber 180 0,0 0,1 2472440 6660 ?? S 6:38pm 0:02.55 /usr/libexec/jabberd/sm -c /etc/jabberd_notification/sm.xml

_jabber 73 0,0 0,1 2438536 4400 ?? Ss 6:38pm 0:00.08 perl -w -x /usr/libexec/jabberd/jabberd -c /etc/jabberd_notification/jabberd.cfg

The output of sudo serveradmin settings calendar:Notifications is:

calendar:Notifications:CoalesceSeconds = 3

calendar:Notifications:Services:XMPPNotifier:CalDAV:SubscriptionURL = "http://myserver:8080/subscription"

calendar:Notifications:Services:XMPPNotifier:CalDAV:APSBundleID = "com.apple.calendar.XServer.d7174125-1f10-45cb-bddb-5f30a3e7c62b"

calendar:Notifications:Services:XMPPNotifier:Host = "myserver"

calendar:Notifications:Services:XMPPNotifier:CardDAV:SubscriptionURL = "http://myserver:8080/subscription"

calendar:Notifications:Services:XMPPNotifier:CardDAV:APSBundleID = "com.apple.contact.XServer.2cb13f54-1305-43f1-8d84-2379759e1c27"

calendar:Notifications:Services:XMPPNotifier:JID = "com.apple.notificationuser@myserver"

calendar:Notifications:Services:XMPPNotifier:Enabled = yes

calendar:Notifications:Services:XMPPNotifier:Service = "twistedcaldav.notify.XMPPNotifierService"

calendar:Notifications:Services:XMPPNotifier:Password = "pvZA3f2YBSqa9HaC"

calendar:Notifications:Services:XMPPNotifier:Port = 5218

calendar:Notifications:Services:XMPPNotifier:ServiceAddress = "pubsub.myserver"

The output of serveradmin settings notification:jabberdClientPortTLS is:

notification:jabberdClientPortTLS = 5218

Hope this helps.

Everything looks good except for that error.log message. I believe that means the jabberd_notification process does not consider "com.apple.notificationuser" to be a privileged user. What does this output for you:

sudo serveradmin settings notification:privilegedUsers

A working system should show "com.apple.notificationuser" in that list.

Mellified: are changes you make to iCal appearing on your iOS device within, say, 10 seconds? If so, then APNS is definitely working. My iOS devices still report they are using "Fetch" even though push is working, so it's a little confusing.

the output is:

serveradmin settings notification:privilegedUsers

notification:privilegedUsers:_array_index:0 = "_notification_user"

notification:privilegedUsers:_array_index:1 = "com.apple.notificationuser"

That seems ok...

Peter Jurg2: hmm, I suppose it's possible your config file is correct but the jabberd_notification processes haven't restarted since the config changed? First try rebooting the server.

If you are still getting the "PubSub node configuration error: <error code='403' type='auth'><forbidden xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error>" messages after the reboot, then I suggest you enable debug logging of the XMPP activity between calendar and jabberd_notification via:

sudo serveradmin settings calendar:LogLevels:twistedcaldav.notify = "debug"

Then restart calendar service. From then on, /var/log/caldavd/error.log will display the actual XMPP commands calendar server sends to the jabber notification server. This might provide a clue as to why the notification server is rejecting them. Here is a sample of what you'll see in /var/log/caldavd/error.log...

2011-10-24 17:12:12-0700 [-] [notifications] 2011-10-24 17:12:12-0700 [InternalNotificationProtocol,1,127.0.0.1] [twistedcaldav.notify.XMPPNotificationFactory#debug] SEND: <iq to='pubsub.example.com' type='set' id='H_7'><pubsub xmlns='http://jabber.org/protocol/pubsub'><create node='/CalDAV/example.com/1E2A5F1F-BE64-4CC6-AA1F-3D0196E36488/'/></pubsub></iq >

2011-10-24 17:12:12-0700 [-] [notifications] 2011-10-24 17:12:12-0700 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] RECV: <iq xmlns='jabber:client' to='com.apple.notificationuser@example.com/icalserver.6a2a0ae6c7d64774aaf38dba3a2fd7c4' from='pubsub.example.com' id='H_7' type='result'/>

2011-10-24 17:12:12-0700 [-] [notifications] 2011-10-24 17:12:12-0700 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] SEND: <iq to='pubsub.example.com' type='get' id='H_8'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/example.com/1E2A5F1F-BE64-4CC6-AA1F-3D0196E36488/'/></pubsub></iq >

2011-10-24 17:12:13-0700 [-] [notifications] 2011-10-24 17:12:13-0700 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] RECV: <iq xmlns='jabber:client' to='com.apple.notificationuser@example.com/icalserver.6a2a0ae6c7d64774aaf38dba3a2fd7c4' from='pubsub.example.com' id='H_8' type='result'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/example.com/1E2A5F1F-BE64-4CC6-AA1F-3D0196E36488/'><x xmlns='jabber:x:data' type='form'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/protocol/pubsub#node_config</value></field><field var='pubsub#persist_items' type='boolean' label='Persist items to storage'><value>true</value></field><field var='pubsub#deliver_payloads' type='boolean' label='Deliver payloads with event notifications'><value>true</value></field></x></configure></pubsub></iq>

2011-10-24 17:12:13-0700 [-] [notifications] 2011-10-24 17:12:13-0700 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] SEND: <iq to='pubsub.example.com' type='set' id='H_9'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/example.com/1E2A5F1F-BE64-4CC6-AA1F-3D0196E36488/'><x xmlns='jabber:x:data' type='submit'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/protocol/pubsub#node_config</value></field><field var='pubsub#persist_items' type='boolean'><value>1</value></field><field var='pubsub#deliver_payloads' type='boolean'><value>1</value></field></x></configure></pubsub></iq>

2011-10-24 17:12:13-0700 [-] [notifications] 2011-10-24 17:12:13-0700 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] RECV: <iq xmlns='jabber:client' to='com.apple.notificationuser@example.com/icalserver.6a2a0ae6c7d64774aaf38dba3a2fd7c4' from='pubsub.example.com' id='H_9' type='result'/>

2011-10-24 17:12:13-0700 [-] [notifications] 2011-10-24 17:12:13-0700 [XmlStream,client] [twistedcaldav.notify.XMPPNotifier#debug] PubSub node /CalDAV/example.com/1E2A5F1F-BE64-4CC6-AA1F-3D0196E36488/ is configured

Please paste the lines leading up to the node configuration error you're seeing, but be sure to remove the references to your domain name for your privacy.

Also, check /var/log/idavoll/error.log for clues -- that's the XMPP notification server's log file.

When you have captured the XMPP logging messages in /var/log/caldavd/error.log, you can set it to a less verbose setting via:

sudo serveradmin settings calendar:LogLevels:twistedcaldav.notify = "warn"

Hi ~morgen, I appreciate your effort! And I am impressed by your in depth knowledge of the system.

I enabled the debugging level for caldav and found a.o. the following in the error logs:

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [InternalNotificationProtocol,3,127.0.0.1] [twistedcaldav.notify.XMPPNotificationFactory#debug] SEND: <iq to='pubsub.myhost' type='set' id='H_240'><pubsub xmlns='http://jabber.org/protocol/pubsub'><create node='/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/'/></pubsub></iq>

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] RECV: <iq xmlns='jabber:client' to='com.apple.notificationuser@myhost/icalserver.d091864f9496458b9d989645ff53545f' from='pubsub.myhost' id='H_240' type='error'><pubsub xmlns='http://jabber.org/protocol/pubsub'><create node='/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/'/></pubsub><error code='409' type='cancel'><conflict xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error></iq>

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] SEND: <iq to='pubsub.myhost' type='get' id='H_241'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/'/></pubsub></iq>

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] RECV: <iq xmlns='jabber:client' to='com.apple.notificationuser@myhost/icalserver.d091864f9496458b9d989645ff53545f' from='pubsub.myhost' id='H_241' type='result'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/'><x xmlns='jabber:x:data' type='form'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/protocol/pubsub#node_config</value></field><field var='pubsub#persist_items' type='boolean' label='Persist items to storage'><value>false</value></field><field var='pubsub#deliver_payloads' type='boolean' label='Deliver payloads with event notifications'><value>false</value></field></x></configure></pubsub></iq>

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] SEND: <iq to='pubsub.myhost' type='set' id='H_242'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/'><x xmlns='jabber:x:data' type='submit'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/protocol/pubsub#node_config</value></field><field var='pubsub#persist_items' type='boolean'><value>1</value></field><field var='pubsub#deliver_payloads' type='boolean'><value>1</value></field></x></configure></pubsub></iq>

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [XmlStream,client] [twistedcaldav.notify.XMPPNotificationFactory#debug] RECV: <iq xmlns='jabber:client' to='com.apple.notificationuser@myhost/icalserver.d091864f9496458b9d989645ff53545f' from='pubsub.myhost' id='H_242' type='error'><pubsub xmlns='http://jabber.org/protocol/pubsub#owner'><configure node='/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/'><x xmlns='jabber:x:data' type='submit'><field var='FORM_TYPE' type='hidden'><value>http://jabber.org/protocol/pubsub#node_config</value></field><field var='pubsub#persist_items' type='boolean'><value>1</value></field><field var='pubsub#deliver_payloads' type='boolean'><value>1</value></field></x></configure></pubsub><error code='403' type='auth'><forbidden xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error></iq>

2011-10-25 13:19:10+0200 [-] [notifications] 2011-10-25 13:19:10+0200 [XmlStream,client] [twistedcaldav.notify.XMPPNotifier#error] PubSub node configuration error: <error code='403' type='auth'><forbidden xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/></error>

It looks like it is tying to create a node that os already there or something (error in the second line). But I have no idea why this happens.

The /var/log/caldavd/error.log is empty for this afternoon. Before that there are lines in like:

2011-10-25 01:20:27+0200 [-] Log opened.

2011-10-25 01:20:27+0200 [-] twistd 11.0.0 (/usr/bin/python2.6 2.6.7) starting up.

2011-10-25 01:20:27+0200 [-] reactor class: twisted.internet.selectreactor.SelectReactor.

2011-10-25 01:20:27+0200 [-] Starting factory <twisted.words.protocols.jabber.xmlstream.XmlStreamFactory object at 0x109c51890>

Let's try resetting your notification databases:

Stop calendar (and addressbook) services via Server.app

See if jabbered_notification processes have stopped as well, and if not, run "serveradmin stop notification"

Move the 3 notification databases out of the way via:

sudo mv /var/db/idavoll/items.db /var/db/idavoll/items.db.orig

sudo mv /var/db/idavoll/pubsub.db /var/db/idavoll/pubsub.db.orig

sudo mv /var/db/apnbridge/apnbridge.db /var/db/apnbridge/apnbridge.db.orig

Start calendar (and/or addressbook) services via Server.app

Re-add your calendar accounts in iCal and in iOS so that the clients re-subscribe to the appropriate calendars (and addressbooks), since when we renamed the database files we effectively got rid of any subscriptions.

See if this gets rid of the configuration errors in /var/log/caldavd/error.log.

I'm curious to know whether there is an entry in /var/db/idavoll/pubsub.db.orig corresponding to your

/CalDAV/<myhost>/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/ node. Can you do this:

cd /var/db/idavoll

sudo sqlite3 pubsub.db.orig

then at the "sqlite>" prompt type:

selct * from nodes;

Is there an entry corresponding to /CalDAV/<myhost>/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/ and if so, what does it show?

Press Control-D to exit sqlite3.

Correction, it should read "select * from nodes;" not "selct"

This solved the problem! Thanks!

The entry in pubsub.db.orig is

4|/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/|1|1|open

There also is an entry

7|/CalDAV/myhost/43732BBB-264E-48A1-8A0B-7AAE9E62E9D5/calendar/|1|1|open

I'm glad that worked. Is the new entry for that node any different than the old entry?