search

st3fan / dovecot-xaps-plugin

MIT License
90 stars 23 forks source link

FIXED! Error: write(/tmp/xapsd.sock) failed: Broken pipe #4

Closed lexusburn closed 8 years ago

lexusburn commented 10 years ago

Hello,

i installed all and deamon seems to working fine, but in maillog i get these messages:

imap(webmaster@foo.de): Error: write(/tmp/xapsd.sock) failed: Broken pipe

and when getting new mail these:

dovecot: lda(webmaster@foo.de): Debug: xaps_plugin_init
dovecot: lda(webmaster@foo.de): Debug: xaps_transaction_begin
dovecot: lda(webmaster@foo.de): Debug: xaps_transaction_begin
dovecot: lda(webmaster@foo.de): Debug: xaps_save_finish
dovecot: lda(webmaster@foo.de): Debug: xaps_transaction_commit
dovecot: lda(webmaster@foo.de): Error: write(/tmp/xapsd.sock) failed: Broken pipe
dovecot: lda(webmaster@foo.de): Error: cannot notify
dovecot: lda(webmaster@foo.de): sieve: msgid=<BE8B9A14-2294-4B03-B3BB-06B0CD79F650@me.com>: stored mail into mailbox 'INBOX'
dovecot: lda(webmaster@foo.de): Debug: xaps_plugin_deinit

i run the deamon in an python virtualenv because i need older version of modules for an old apple calendarserver installation.

here output from daemon:

2014-10-22 16:05:29+0200 [-] Log opened.
2014-10-22 16:05:29+0200 [-] twistd 14.0.0 (/usr/local/src/dovecot-xaps-daemon-master/foo/bin/python 2.6.8) starting up.
2014-10-22 16:05:29+0200 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2014-10-22 16:05:29+0200 [-] XAPSFactory starting on '/tmp/xapsd.sock'
2014-10-22 16:05:29+0200 [-] Starting factory <xaps.XAPSFactory instance at 0xa58ae2c>
2014-10-22 16:05:29+0200 [-] Starting factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:05:29+0200 [-] APNSClientFactory.startedConnecting
2014-10-22 16:05:59+0200 [-] APNSClientFactory.clientConnectionFailed
2014-10-22 16:05:59+0200 [-] <twisted.internet.tcp.Connector instance at 0x9a1f0ac> will retry in 3 seconds
2014-10-22 16:05:59+0200 [-] Stopping factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:06:03+0200 [-] Starting factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:06:03+0200 [-] APNSClientFactory.startedConnecting
2014-10-22 16:06:33+0200 [-] APNSClientFactory.clientConnectionFailed
2014-10-22 16:06:33+0200 [-] <twisted.internet.tcp.Connector instance at 0x9a1f0ac> will retry in 8 seconds
2014-10-22 16:06:33+0200 [-] Stopping factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:06:42+0200 [-] Starting factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:06:42+0200 [-] APNSClientFactory.startedConnecting
2014-10-22 16:07:12+0200 [-] APNSClientFactory.clientConnectionFailed
2014-10-22 16:07:12+0200 [-] <twisted.internet.tcp.Connector instance at 0x9a1f0ac> will retry in 19 seconds
2014-10-22 16:07:12+0200 [-] Stopping factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:07:31+0200 [-] Starting factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:07:31+0200 [-] APNSClientFactory.startedConnecting
2014-10-22 16:07:57+0200 [XAPSProtocol,0,] lineReceived: REGISTER aps-account-id="AE60FB89-31F6-4A90-9A3E-66B0802E6797" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="foo@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-22 16:07:57+0200 [XAPSProtocol,0,] Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:07:57+0200 [XAPSProtocol,0,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:07:57+0200 [XAPSProtocol,1,] lineReceived: REGISTER aps-account-id="F1AA61EF-FC51-4231-8AA3-408CA3286200" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="webmaster@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-22 16:07:57+0200 [XAPSProtocol,1,] Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:07:57+0200 [XAPSProtocol,1,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:08:01+0200 [-] APNSClientFactory.clientConnectionFailed
2014-10-22 16:08:01+0200 [-] <twisted.internet.tcp.Connector instance at 0x9a1f0ac> will retry in 62 seconds
2014-10-22 16:08:01+0200 [-] Stopping factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:08:02+0200 [XAPSProtocol,2,] lineReceived: REGISTER aps-account-id="F1AA61EF-FC51-4231-8AA3-408CA3286200" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="webmaster@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-22 16:08:02+0200 [XAPSProtocol,2,] Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:08:02+0200 [XAPSProtocol,2,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:08:03+0200 [XAPSProtocol,3,] lineReceived: REGISTER aps-account-id="AE60FB89-31F6-4A90-9A3E-66B0802E6797" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="foo@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-22 16:08:03+0200 [XAPSProtocol,3,] Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:08:03+0200 [XAPSProtocol,3,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-22 16:09:04+0200 [-] Starting factory <apns.APNSClientFactory instance at 0x96a7aec>
2014-10-22 16:09:04+0200 [-] APNSClientFactory.startedConnecting
2014-10-22 16:09:34+0200 [-] APNSClientFactory.clientConnectionFailed
2014-10-22 16:09:34+0200 [-] <twisted.internet.tcp.Connector instance at 0x9a1f0ac> will retry in 154 seconds
2014-10-22 16:09:34+0200 [-] Stopping factory <apns.APNSClientFactory instance at 0x96a7aec>
lexusburn commented 10 years ago

Ok, fixed APNSClientFactory.clientConnectionFailed:

2014-10-22 16:25:35+0200 [-] Log opened.
2014-10-22 16:25:35+0200 [-] twistd 14.0.0 (/usr/local/src/dovecot-xaps-daemon-master/foo/bin/python 2.6.8) starting up.
2014-10-22 16:25:35+0200 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2014-10-22 16:25:35+0200 [-] XAPSFactory starting on '/tmp/xapsd.sock'
2014-10-22 16:25:35+0200 [-] Starting factory <xaps.XAPSFactory instance at 0x9346e2c>
2014-10-22 16:25:35+0200 [-] Starting factory <apns.APNSClientFactory instance at 0x8463aec>
2014-10-22 16:25:35+0200 [-] APNSClientFactory.startedConnecting
2014-10-22 16:25:35+0200 [Uninitialized] APNSClientFactory.buildProtocol
2014-10-22 16:25:35+0200 [Uninitialized] APNSProtocol.connectionMade
2014-10-22 16:25:35+0200 [Uninitialized] APNSClientFactory.clientConnectionMade
2014-10-22 16:26:11+0200 [XAPSProtocol,0,] lineReceived: REGISTER aps-account-id="F1AA61EF-FC51-4231-8AA3-408CA3286200" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="webmaster@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")

i had to open outgoing TCP Ports 2195,2196.

But i still get the broken pipe error for the socket. :-(

lexusburn commented 10 years ago

perhaps a problem with user rights?

lexusburn commented 10 years ago

these are my active modules in my first virtual enviroment:

Python          - 2.6.8        - active development (/usr/lib/python2.6/lib-dynload)
Twisted         - 14.0.0       - active 
argparse        - 1.2.1        - active 
cffi            - 0.8.6        - active 
characteristic  - 14.1.0       - active 
cryptography    - 0.6.1        - active 
dovecot-xaps-daemon - 0.2          - active 
pip             - 0.8.1        - active 
pyOpenSSL       - 0.14         - active 
pyasn1-modules  - 0.0.5        - active 
pyasn1          - 0.1.7        - active 
pycparser       - 2.10         - active 
service-identity - 14.0.0       - active 
setuptools      - 0.6c11       - active 
six             - 1.8.0        - active 
wsgiref         - 0.1.2        - active development (/usr/lib/python2.6)
yolk            - 0.4.3        - active 
zope.interface  - 4.1.1        - active

and these in my second virtual enviroment:

Python          - 2.7.8        - active development (/usr/local/src/python278/.localpython/lib/python2.7/lib-dynload)
Twisted         - 14.0.0       - active 
cffi            - 0.8.6        - active 
characteristic  - 14.1.0       - active 
cryptography    - 0.6.1        - active 
dovecot-xaps-daemon - 0.2          - active 
pip             - 0.8.1        - active 
pyOpenSSL       - 0.14         - non-active development (/root/.local/lib/python2.7/site-packages/pyOpenSSL-0.14-py2.7.egg)
pyOpenSSL       - 0.14         - non-active development (/root/.local/lib/python2.7/site-packages/pyOpenSSL-0.14-py2.7.egg)
pyOpenSSL       - 0.14         - active 
pyOpenSSL       - 0.14         - active 
pyasn1-modules  - 0.0.5        - active 
pyasn1          - 0.1.7        - active 
pycparser       - 2.10         - active 
service-identity - 14.0.0       - active 
setuptools      - 0.6c11       - non-active 
setuptools      - 7.0          - active 
six             - 1.8.0        - active 
wsgiref         - 0.1.2        - active development (/usr/local/src/python278/.localpython/lib/python2.7)
yolk            - 0.4.3        - active 
zope.interface  - 4.1.1        - active

both get the same error:

Error: write(/tmp/xapsd.sock) failed: Broken pipe
st3fan commented 10 years ago

The first hint is APNSClientFactory.clientConnectionFailed .. I'll add some extra logging that should print the reason. Can you give that a try?

lexusburn commented 10 years ago

The APNSClientFactory.clientConnectionFailed had i fixed. It was a problem with the port that i had to open outgoing port. Have a look on my other comments. ;-)

But i will try your new version. :-)

lexusburn commented 10 years ago

ok, here is what i got when i'm using the new version of the daemon:

2014-10-29 11:23:00+0100 [-] Log opened.
2014-10-29 11:23:00+0100 [-] twistd 14.0.2 (/usr/local/src/dovecot-xaps-daemon/virt_env/virt1/bin/python 2.7.8) starting up.
2014-10-29 11:23:00+0100 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2014-10-29 11:23:00+0100 [-] XAPSFactory starting on '/var/run/dovecot/xapsd.sock'
2014-10-29 11:23:00+0100 [-] Starting factory <xapsd.xaps.XAPSFactory instance at 0xb6d84fac>
2014-10-29 11:23:00+0100 [-] Starting factory <xapsd.apns.APNSClientFactory instance at 0xb6d84e8c>
2014-10-29 11:23:00+0100 [-] APNSClientFactory.startedConnecting
2014-10-29 11:23:01+0100 [Uninitialized] APNSClientFactory.buildProtocol
2014-10-29 11:23:01+0100 [Uninitialized] APNSProtocol.connectionMade
2014-10-29 11:23:01+0100 [Uninitialized] APNSClientFactory.clientConnectionMade
2014-10-29 11:23:55+0100 [XAPSProtocol,0,] lineReceived: REGISTER aps-account-id="F1AA61EF-FC51-4231-8AA3-408CA3286200" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="webmaster@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-29 11:23:55+0100 [XAPSProtocol,0,] Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:23:55+0100 [XAPSProtocol,0,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:23:56+0100 [XAPSProtocol,1,] lineReceived: REGISTER aps-account-id="AE60FB89-31F6-4A90-9A3E-66B0802E6797" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="foo@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-29 11:23:56+0100 [XAPSProtocol,1,] Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:23:56+0100 [XAPSProtocol,1,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:24:03+0100 [XAPSProtocol,2,] lineReceived: REGISTER aps-account-id="F1AA61EF-FC51-4231-8AA3-408CA3286200" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="webmaster@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-29 11:24:03+0100 [XAPSProtocol,2,] Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:24:03+0100 [XAPSProtocol,2,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'F1AA61EF-FC51-4231-8AA3-408CA3286200', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'webmaster@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:24:04+0100 [XAPSProtocol,3,] lineReceived: REGISTER aps-account-id="AE60FB89-31F6-4A90-9A3E-66B0802E6797" aps-device-token="6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A" aps-subtopic="com.apple.mobilemail" dovecot-username="foo@foo.de" dovecot-mailboxes=("INBOX","INBOX.Sent")
2014-10-29 11:24:04+0100 [XAPSProtocol,3,] Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:24:04+0100 [XAPSProtocol,3,] handleRegister: Command(name='REGISTER', args={'aps-account-id': 'AE60FB89-31F6-4A90-9A3E-66B0802E6797', 'aps-device-token': '6164381EB6E9A4CC36308A23A05A35C29C5363648452B6ACD79B3FDB3741D19A', 'dovecot-mailboxes': ['INBOX', 'INBOX.Sent'], 'dovecot-username': 'foo@foo.de', 'aps-subtopic': 'com.apple.mobilemail'})
2014-10-29 11:32:32+0100 [XAPSProtocol,4,] lineReceived: NOTIFY dovecot-username="foo@oo.de" dovecot-mailbox="INBOX"
2014-10-29 11:32:32+0100 [XAPSProtocol,4,] Command(name='NOTIFY', args={'dovecot-username': 'foo@foo.de', 'dovecot-mailbox': 'INBOX'})
2014-10-29 11:32:32+0100 [XAPSProtocol,4,] handleNotify: Command(name='NOTIFY', args={'dovecot-username': 'foo@foo.de', 'dovecot-mailbox': 'INBOX'})
2014-10-29 11:32:32+0100 [XAPSProtocol,4,] APNSClientFactory.queueNotification
2014-10-29 11:32:33+0100 [-] APNSProtocol.sendNotifications (1)

and from dovecot:

Oct 29 11:23:24 mymailserver dovecot: master: Dovecot v2.2.4 starting up (core dumps disabled)
Oct 29 11:23:24 mymailserver dovecot: imap-login: Login: user=<webmaster@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18839, TLS, session=<+tJiJ40GGQDZRUD+>
Oct 29 11:23:24 mymailserver dovecot: imap-login: Login: user=<webmaster@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18841, TLS, session=<hYRlJ40GGwDZRUD+>
Oct 29 11:23:24 mymailserver dovecot: imap-login: Login: user=<webmaster@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18849, TLS, session=<7StoJ40GHADZRUD+>
Oct 29 11:23:25 mymailserver dovecot: imap-login: Login: user=<webmaster@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18855, TLS, session=<99lqJ40GHQDZRUD+>
Oct 29 11:23:25 mymailserver dovecot: imap-login: Login: user=<foo@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18858, TLS, session=<VRN1J40GHgDZRUD+>
Oct 29 11:23:25 mymailserver dovecot: imap-login: Login: user=<foo@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18860, TLS, session=<QqZ3J40GHwDZRUD+>
Oct 29 11:23:26 mymailserver dovecot: imap-login: Login: user=<foo@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18862, TLS, session=<PH56J40GIADZRUD+>
Oct 29 11:23:26 mymailserver dovecot: imap-login: Login: user=<foo@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=18864, TLS, session=<CEV9J40GIQDZRUD+>
Oct 29 11:23:34 mymailserver dovecot: imap-login: Login: user=<calendarserver@foo.de>, method=PLAIN, rip=217.69.77.122, lip=217.69.77.122, mpid=18928, TLS, session=<twD1J40GDQDZRU16>
Oct 29 11:23:34 mymailserver dovecot: imap(calendarserver@foo.de): Disconnected: Logged out in=68 out=815
Oct 29 11:23:55 mymailserver dovecot: imap-login: Login: user=<webmaster@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=19056, TLS, session=<a6Y4KY0GmwDZRUD+>
Oct 29 11:23:55 mymailserver dovecot: imap(webmaster@foo.de): Error: write(/var/run/dovecot/xapsd.sock) failed: Broken pipe
Oct 29 11:23:56 mymailserver dovecot: imap-login: Login: user=<foo@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=19069, TLS, session=<d1dIKY0GmgDZRUD+>
Oct 29 11:23:56 mymailserver dovecot: imap(foo@foo.de): Error: write(/var/run/dovecot/xapsd.sock) failed: Broken pipe
Oct 29 11:24:03 mymailserver dovecot: imap-login: Login: user=<webmaster@foo.de>, method=PLAIN, rip=217.69.64.254, lip=217.69.77.122, mpid=19117, TLS, session=<QZi7KY0GoQDZRUD+>
Oct 29 11:32:25 mymailserver postfix/smtpd[22361]: connect from pmta40180.emarsys.net[91.211.240.180]
Oct 29 11:32:25 mymailserver postfix/smtpd[22361]: DD6C247005B: client=pmta40180.emarsys.net[91.211.240.180]
Oct 29 11:32:25 mymailserver postfix/cleanup[22368]: DD6C247005B: message-id=<0.1.4D.250.1CFF363A1589C5A.0@pmta40180.emarsys.net>
Oct 29 11:32:25 mymailserver postfix/qmgr[28479]: DD6C247005B: from=<foobar@emarsys.net>, size=39187, nrcpt=1 (queue active)
Oct 29 11:32:26 mymailserver postfix/smtpd[22361]: disconnect from pmta40180.emarsys.net[91.211.240.180]
Oct 29 11:32:32 mymailserver postfix/smtpd[22424]: connect from localhost.localdomain[127.0.0.1]
Oct 29 11:32:32 mymailserver postfix/smtpd[22424]: D04EB9E000C: client=localhost.localdomain[127.0.0.1]
Oct 29 11:32:32 mymailserver postfix/cleanup[22368]: D04EB9E000C: message-id=<0.1.4D.250.1CFF363A1589C5A.0@pmta40180.emarsys.net>
Oct 29 11:32:32 mymailserver postfix/qmgr[28479]: D04EB9E000C: from=<foobar@emarsys.net>, size=39992, nrcpt=1 (queue active)
Oct 29 11:32:32 mymailserver postfix/smtpd[22424]: disconnect from localhost.localdomain[127.0.0.1]
Oct 29 11:32:32 mymailserver amavis[23628]: (23628-09) Passed CLEAN, [91.211.240.180] [91.211.240.180] <foobar@emarsys.net> -> <foo@foo.de>, Message-ID: <0.1.4D.250.1CFF363A1589C5A.0@pmta40180.emarsys.net>, Hits: 2.411, 6907 ms
Oct 29 11:32:32 mymailserver postfix/lmtp[22369]: DD6C247005B: to=<foo@foo.de>, orig_to=<foo2@foo.de>, relay=127.0.0.1[127.0.0.1]:10024, delay=7.1, delays=0.23/0.01/0/6.9, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=23628-09, from MTA: 250 2.0.0 Ok: queued as D04EB9E000C)
Oct 29 11:32:32 mymailserver postfix/qmgr[28479]: DD6C247005B: removed
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Debug: xaps_plugin_init
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Debug: xaps_transaction_begin
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Debug: xaps_transaction_begin
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Debug: xaps_save_finish
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Debug: xaps_transaction_commit
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Error: write(/var/run/dovecot/xapsd.sock) failed: Broken pipe
Oct 29 11:32:32 mymailserver dovecot: lda(foo@foo.de): Error: cannot notify
Oct 29 11:32:33 mymailserver dovecot: lda(foo@foo.de): sieve: msgid=<0.1.4D.250.1CFF363A1589C5A.0@pmta40180.emarsys.net>: stored mail into mailbox 'INBOX'
Oct 29 11:32:33 mymailserver dovecot: lda(foo@foo.de): Debug: xaps_plugin_deinit
Oct 29 11:32:33 mymailserver postfix/pipe[22425]: D04EB9E000C: to=<foo@foo.de>, relay=dovecot, delay=0.21, delays=0.05/0.01/0/0.16, dsn=2.0.0, status=sent (delivered via dovecot service)
Oct 29 11:32:33 mymailserver postfix/qmgr[28479]: D04EB9E000C: removed

As you can see in log from dovecot the last login lines are from my iphone. Here i get these Error: write(/var/run/dovecot/xapsd.sock) failed: Broken pipe messages. But on the deamon side all seems to be fine. No errors there.

Same for notification on new email. Error in dovecot log. All seems to be ok on daemon-side.

And sure, i'm using the same socket on deamon and dovecot-plugin, as you can see in logs. ;-)

here my packages i'm using:

Python          - 2.7.8        - active development (/usr/local/src/python278/.localpython/lib/python2.7/lib-dynload)
Twisted         - 14.0.2       - active 
cffi            - 0.8.6        - active 
characteristic  - 14.1.0       - active 
cryptography    - 0.6.1        - active 
dovecot-xaps-daemon - 0.2          - active 
pip             - 0.8.1        - active 
pyOpenSSL       - 0.14         - active development (/root/.local/lib/python2.7/site-packages/pyOpenSSL-0.14-py2.7.egg)
pyasn1-modules  - 0.0.5        - active 
pyasn1          - 0.1.7        - active 
pycparser       - 2.10         - active 
service-identity - 14.0.0       - active 
setuptools      - 0.6c11       - non-active 
setuptools      - 7.0          - active 
six             - 1.8.0        - active 
wsgiref         - 0.1.2        - active development (/usr/local/src/python278/.localpython/lib/python2.7)
yolk            - 0.4.3        - active 
zope.interface  - 4.1.1        - active
st3fan commented 10 years ago

The problem could be Dovecot 2.2. I have only really tested with Dovecot 2.0 (Ubuntu 12.04/LTS).

I'll have to make a test setup to find out if that is the case.

lexusburn commented 10 years ago

thank you. i'm waiting for your test results then.

lexusburn commented 10 years ago

Is it possible that i need to open other ports then 2195 and 2196? Do i need INCOMING ports open?

PDXmoose commented 10 years ago

I've got the same issue: Environment: Ubuntu 14.04, Dovecot 2.2

After seeing the same issues, I decided to debug the xapsd socket, the dump of that traffic via socat is at the bottom (its also why the socket's don't match up, socat is acting as a man in the middle, but this was only the case after I started debugging this issue)

The issue also seems to exist regardless of is LMTP or the LDA is used (exact same result with both)

From the mail log:

Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: xaps_transaction_begin
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: Destination address: xx@example.com (source: -a parameter)
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: sieve: user has no valid location for a personal script
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: sieve: no scripts to execute: reverting to default delivery.
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: xaps_transaction_begin
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: xaps_save_finish
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: xaps_transaction_commit
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Error: write(/tmp/xapsd.sock) failed: Broken pipe
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Error: cannot notify
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): msgid=<8E9DFB20-2FA1-4BB5-9612-AD9A369B7CFA@devsecgru.com>: saved mail to INBOX
Nov  3 11:17:25 mx21 dovecot: lda(xx@example.com): Debug: xaps_plugin_deinit

From the xaps daemon:

twistd -n xapsd --key=/etc/xapsd/key.pem --certificate=/etc/xapsd/certificate.pem --database=/usr/local/xapsd/xapsd.json --socket=/tmp//xapsd2.sock

2014-11-03 11:17:15-0800 [-] Log opened.
2014-11-03 11:17:15-0800 [-] twistd 13.2.0 (/usr/bin/python 2.7.6) starting up.
2014-11-03 11:17:15-0800 [-] reactor class: twisted.internet.epollreactor.EPollReactor.
2014-11-03 11:17:15-0800 [-] XAPSFactory starting on '/tmp//xapsd2.sock'
2014-11-03 11:17:15-0800 [-] Starting factory <xapsd.xaps.XAPSFactory instance at 0x7f9050512170>
2014-11-03 11:17:15-0800 [-] Starting factory <xapsd.apns.APNSClientFactory instance at 0x7f9050512050>
2014-11-03 11:17:15-0800 [-] APNSClientFactory.startedConnecting
2014-11-03 11:17:15-0800 [Uninitialized] APNSClientFactory.buildProtocol
2014-11-03 11:17:15-0800 [Uninitialized] APNSProtocol.connectionMade
2014-11-03 11:17:15-0800 [Uninitialized] APNSClientFactory.clientConnectionMade
2014-11-03 11:17:25-0800 [XAPSProtocol,0,] lineReceived: NOTIFY dovecot-username="xx@example.com"   dovecot-mailbox="INBOX"
2014-11-03 11:17:25-0800 [XAPSProtocol,0,] Command(name='NOTIFY', args={'dovecot-username': 'xx@example.com', 'dovecot-mailbox': 'INBOX'})
2014-11-03 11:17:25-0800 [XAPSProtocol,0,] handleNotify: Command(name='NOTIFY', args={'dovecot-username': 'xx@example.com', 'dovecot-mailbox': 'INBOX'})

SOCAT output:


[root@mx21 ~]# socat -x unix-listen:/tmp/xapsd.sock,fork unix:/tmp/xapsd2.sock 
> 2014/11/03 11:17:25.727481  length=70 from=0 to=69

 4e 4f 54 49 46 59 20 64 6f 76 65 63 6f 74 2d 75 73 65 72 6e 61 6d 65 3d 22 6b 69 6c 6f 40 64 65 76 73 65 63 67 72 75 2e 63 6f 6d 22 09 64 6f 76 65 63 6f 74 2d 6d 61 69 6c 62 6f 78 3d 22 49 4e 42 4f 58 22 0d 0a
PDXmoose commented 10 years ago

Update: as per the comment here: https://github.com/st3fan/dovecot-xaps-plugin/issues/3#issuecomment-61505339

I tested the suggestion of using the system socket.h files rather then dovecot's net.h file, but to no aval, the "Error: write(/tmp/xapsd.sock) failed: Broken pipe" issue persists.

PDXmoose commented 10 years ago

Resolved for me, likely will fix other's issues with this:

This is a dovecot bug, patched by upgrading to 2.2.15 from 2.2.9 (for ubuntu 14.04, I used these pre-built packages: http://download.opensuse.org/repositories/home:/sbosch:/dovecot-2.2/xUbuntu_14.04/ )

using clean non-patched versions of the xaps plugins, and after restarting dovecot, the issue with broken pipe goes away and push notifications started working.

st3fan commented 10 years ago

Thank you for the great analysis @PDXmoose ..

lexusburn commented 10 years ago

ok, works for me now with new dovecot version (2.2.15) too. :-) had 2.2.4 before...

no errors now, and i get notifications right on my iphone. :-)

disorderlydrunk commented 10 years ago

Great, upgrading dovecot to 2.2.15 solved everything for me to!