Overall, I am not having any problems with email notifications of any kind. However, I just found out that one user received three voicemail notifications from Thursday and Friday of last week today. They were each sent one minute apart.
We use Google Apps for email, and he accesses his email from the web client. So I would think it is either a SMTP issue or FreePBX configuration issue on our PBX.
Has anyone seen something like this before? Where should I be looking to troubleshoot it?
Your mail log files, typically /var/log/mail.log or /var/log/maillog depending on how you setup your system.
Hmm…so the messages were sent to the SMTP server today. Oddly, there is a mention of the network being unreachable, but each message does go through, as shown by the OK status. The network unreachable is not exclusive to these problem messages, so wonder if that is unrelated to the delayed sending.
Anything stand out?
Dec 8 15:30:13 localhost postfix/pickup[35628]: 9ECC760641: uid=499 from=<asterisk>
Dec 8 15:30:13 localhost postfix/cleanup[45397]: 9ECC760641: message-id=<[email protected]>
Dec 8 15:30:13 localhost postfix/qmgr[1412]: 9ECC760641: from=<[email protected]>, size=523659, nrcpt=1 (queue active)
Dec 8 15:30:13 localhost postfix/smtp[45401]: connect to smtp.gmail.com[2607:f8b0:4002:c09::6c]:587: Network is unreachable
Dec 8 15:30:17 localhost postfix/smtp[45401]: 9ECC760641: to=<[email protected]>, relay=smtp.gmail.com[64.233.176.108]:587, delay=3.6, delays=0.11/0.05/0.77/2.7, dsn=2.0.0, status=sent (250 2.0.0 OK 1418070617 28sm23733286yhw.17 - gsmtp)
Dec 8 15:30:17 localhost postfix/qmgr[1412]: 9ECC760641: removed
Dec 8 15:31:09 localhost postfix/pickup[35628]: 97BE160643: uid=499 from=<asterisk>
Dec 8 15:31:09 localhost postfix/cleanup[45397]: 97BE160643: message-id=<[email protected]>
Dec 8 15:31:09 localhost postfix/qmgr[1412]: 97BE160643: from=<[email protected]>, size=253527, nrcpt=1 (queue active)
Dec 8 15:31:09 localhost postfix/smtp[45401]: connect to smtp.gmail.com[2607:f8b0:4002:c07::6d]:587: Network is unreachable
Dec 8 15:31:12 localhost postfix/smtp[45401]: 97BE160643: to=<[email protected]>, relay=smtp.gmail.com[74.125.21.109]:587, delay=2.6, delays=0.09/0/0.72/1.8, dsn=2.0.0, status=sent (250 2.0.0 OK 1418070672 d4sm23719513yhd.43 - gsmtp)
Dec 8 15:31:12 localhost postfix/qmgr[1412]: 97BE160643: removed
Dec 8 15:32:12 localhost postfix/pickup[35628]: 8FEA360645: uid=499 from=<asterisk>
Dec 8 15:32:12 localhost postfix/cleanup[45397]: 8FEA360645: message-id=<[email protected]>
Dec 8 15:32:12 localhost postfix/qmgr[1412]: 8FEA360645: from=<[email protected]>, size=837639, nrcpt=1 (queue active)
Dec 8 15:32:12 localhost postfix/smtp[45401]: connect to smtp.gmail.com[2607:f8b0:4002:c07::6d]:587: Network is unreachable
Dec 8 15:32:15 localhost postfix/smtp[45401]: 8FEA360645: to=<[email protected]>, relay=smtp.gmail.com[64.233.176.108]:587, delay=3, delays=0.09/0/0.67/2.2, dsn=2.0.0, status=sent (250 2.0.0 OK 1418070735 10sm23719648yhq.46 - gsmtp)
Dec 8 15:32:15 localhost postfix/qmgr[1412]: 8FEA360645: removedNo, it is because you have IPV6 enabled but not routeable (2607:f8b0:4002:c07::6d), it finds gmail on IPV4 (64.233.176.108) no problem, to save yourself confusion, you should disable IPV6.
I doubt whetehre gmail will actually send your emails to [email protected] though 
Good call on the IPv6!
As far as the delayed messages, where else should I look? I see a reference to a message id in the mailllog (shown above). What log should I look in to see the details for that message id, assuming some have been logged? I looked in the full asterisk logs for the two days when the messages were recorded and should have been mailed, but could not find the message IDs.
Just the postfix log to see why your mails are delayed. But as I say gmail will balk at sending emails from localhost.localdomain and sending to [email protected] will also likely cause their mailservers to delay your mails.
Thanks for all your help!
Turns out it was actually a misunderstanding. The voicemails were originally left on our reception extension, then our receptionist transferred them to that user (all within seconds of each other a couples days later). We haven’t had the system in place very long, so this was the first time this has been done. As it turns out, the timestamps in the email match the original message (that was when it was left after all), which confused the user.
I’m glad this came up the way it did as it ended up pointing out minor issues to be corrected with our IPv6 and SMTP settings.