Bug 383304 - Sent emails are stuck in outbox
Summary: Sent emails are stuck in outbox
Status: RESOLVED FIXED
Alias: None
Product: Akonadi
Classification: Frameworks and Libraries
Component: Mail Dispatcher Agent (show other bugs)
Version: GIT (master)
Platform: Compiled Sources Linux
: NOR normal
Target Milestone: ---
Assignee: kdepim bugs
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-08-09 08:36 UTC by Christophe Marin
Modified: 2017-08-16 15:56 UTC (History)
2 users (show)

See Also:
Latest Commit:
Version Fixed In:

Attachments
gdb bt full (6.42 KB, text/plain)
2017-08-10 22:21 UTC, Allen Winter 		Details
gdb thread apply all bt full (8.82 KB, text/plain)
2017-08-10 22:21 UTC, Allen Winter 		Details
View All Add an attachment

Note You need to log in before you can comment on or make changes to this bug.
Description Christophe Marin 2017-08-09 08:36:50 UTC 
Using master.

This started ~2 weeks ago but I didn't have time to rebuild all the pim modules from scratch.

Symptom : sent messages (any account / identity) are stuck in outbox and never sent.

Restarting the akonadi server doesn't help,
Removing, reinstalling the maildispatcher agent also has no effect,
Settings are correct for all accounts
Comment 1 Christophe Marin 2017-08-09 08:50:05 UTC 
Running fsck is not an option due to bug 379153

Log whem rmb'ing / send queued messages : 

-yuuko- krop 10:48 /kde/build/5/pim/pim-sieve-editor # 10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::DataStore::open: Database "akonadi" opened using driver "QPSQL"
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchRequest::exec: Executing search "searchUpdate-1502268500"
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiplugin_indexer: SearchPlugin::search: Got 0 results
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::searchUpdateResultsAvailable: searchUpdateResultsAvailable 494 0 results
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::searchUpdateResultsAvailable: Got 0 results, out of which 0 are already in the collection
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::searchUpdateResultsAvailable: Added results: 0 (fast path)
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchRequest::exec: Search done "searchUpdate-1502268500" (without remote search)
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::updateSearchImpl: Search update finished
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::updateSearchImpl: All results: 0
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::updateSearchImpl: Removed results: 0
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchRequest::exec: Executing search "searchUpdate-1502268500"
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiplugin_indexer: SearchPlugin::search: Got 0 results
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::searchUpdateResultsAvailable: searchUpdateResultsAvailable 495 0 results
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::searchUpdateResultsAvailable: Got 0 results, out of which 0 are already in the collection
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::searchUpdateResultsAvailable: Added results: 0 (fast path)
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchRequest::exec: Search done "searchUpdate-1502268500" (without remote search)
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::updateSearchImpl: Search update finished
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::updateSearchImpl: All results: 0
10:48:20 - akonadiserver(11158) - org.kde.pim.akonadiserver: Akonadi::Server::SearchManager::updateSearchImpl: Removed results: 0
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 440844 is accepted into the queue (size 550 ).
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::dispatch: Attempting to dispatch the next message.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 440844 is ignored.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 440844 is ignored.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::itemFetched: Fetched item 440844 ; creating SendJob.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: SendJob::Private::doTransport: Transporting message.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.mailtransport: MailTransport::Transport::Transport: "1718429139"
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: SendJob::Private::doPostJob: success false message "Server error"
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: SendJob::Private::doPostJob: Error transporting.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: SendJob::Private::storeResult: success false message "Failed to transport message. Server error"
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: StoreResultJob::Private::fetchDone: 
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: StoreResultJob::Private::modifyDone: 
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: SendJob::Private::doEmitResult: Success storing result.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::sendResult: Sending failed. error: "Failed to transport message. Server error"
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.knotifications: KNotificationManager::notify: Calling notify on "Popup"
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::dispatch: Empty queue.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 440844 is queued to be sent manually.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 440844 is queued to be sent manually.
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.ksmtp: : Socket error: 2
10:48:20 - akonadi_maildispatcher_agent(11226) - org.kde.pim.ksmtp: : Socket error: 2
Comment 2 Allen Winter 2017-08-09 12:54:01 UTC 
I've had this as well since we changed over to the new ksmtp.  although I really have no idea if that's just a coincidence.  I've spent quite some time on it and never found any clues as to what might be happening.
Comment 3 Christophe Marin 2017-08-10 18:34:13 UTC 
More things were rebuilt...

KMail log on rmb / send queued messages : 
20:32:20 - kmail2(1881) - org.kde.pim.messagecomposer: MessageComposer::AkonadiSender::doSendQueued: Sending queued message with custom transport: -1
20:32:20 - kmail2(1881) - org.kde.pim.mailtransportakonadi: Akonadi::FilterActionJob::doStart: Fetching collection 1385
20:32:20 - kmail2(1881) - org.kde.pim.mailtransportakonadi: Akonadi::FilterActionJob::Private::traverseItems: Traversing 1 items.
20:32:20 - kmail2(1881) - org.kde.pim.mailtransportakonadi: Akonadi::FilterActionJob::Private::traverseItems: Added subjob for item 441780
20:32:20 - kmail2(1881) - org.kde.pim.mailtransportakonadi: Akonadi::FilterActionJob::Private::traverseItems: Have subjobs; Done when last of them is
20:32:20 - kmail2(1881) - org.kde.pim.mailtransportakonadi: MailTransport::DispatcherInterfacePrivate::massModifyResult: succeeded.

---

maildispatcher log :

20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 441780 is accepted into the queue (size 529 ).
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::dispatch: Attempting to dispatch the next message.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 441780 is ignored.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 441780 is ignored.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::itemFetched: Fetched item 441780 ; creating SendJob.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: SendJob::Private::doTransport: Transporting message.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.mailtransport: MailTransport::Transport::Transport: "1468434794"
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: SendJob::Private::doPostJob: success false message "Server error"
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: SendJob::Private::doPostJob: Error transporting.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: SendJob::Private::storeResult: success false message "Failed to transport message. Server error"
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: StoreResultJob::Private::fetchDone: 
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: StoreResultJob::Private::modifyDone: 
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: SendJob::Private::doEmitResult: Success storing result.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::sendResult: Sending failed. error: "Failed to transport message. Server error"
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.knotifications: KNotificationManager::notify: Calling notify on "Popup"
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: MailDispatcherAgent::Private::dispatch: Empty queue.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 441780 is queued to be sent manually.
20:32:20 - akonadi_maildispatcher_agent(32354) - org.kde.pim.maildispatcher: OutboxQueue::Private::addIfComplete: Item 441780 is queued to be sent manually.
Comment 4 Allen Winter 2017-08-10 22:16:35 UTC 
I see:
org.kde.pim.libkdepim: "Sending messages"

and the message does seem to be sent ok.
but never moved from outbox to sent-mail
also I get a core from akonadi_maildispatcher_agent

I will attach backtraces
Comment 5 Allen Winter 2017-08-10 22:21:24 UTC 
Created attachment 107204 [details]
gdb bt full
Comment 6 Allen Winter 2017-08-10 22:21:47 UTC 
Created attachment 107205 [details]
gdb thread apply all bt full
Comment 7 Allen Winter 2017-08-10 22:58:06 UTC 
if I comment out the Q_ASSERT(currentJob == job); lines in several places things work better.
Comment 8 Christophe Marin 2017-08-11 08:31:16 UTC 
maybe another issue then ? It doesn't crash here.
Comment 9 Allen Winter 2017-08-16 15:01:57 UTC 
Dan fixed the assert problem so I'm good now.
Comment 10 Christophe Marin 2017-08-16 15:56:33 UTC 
After wiping and reinstalling everything, I had the same crash as you and it's indeed gone since the last commit.