Sending emails with MfE (Exchange) fails [released]
asked 2014-02-01 23:57:55 +0200
Hi!
Sometimes emails won't be send and a sync error is being shown on the email cover. It's seems like it has something to do with the size of the email, small emails tend to work, though I'm not 100% sure. I'm using the latest update (0.1.28-10.11.1.jolla). On the server site my provider is using Open Xchange (6.22.5 Rev5). Here's the as-daemon log output (replaced some domains, session keys and databuffer with "xx"):
[1001] Feb. 01 21:13:09 [Debug] General : AsProtocol job AsProtocolJob(0x11d0538) , about to send a request
[1001] Feb. 01 21:13:09 [Debug] AS_LIB : Creating request for command SendMail
[1001] Feb. 01 21:13:09 [Debug] Network : QtConnectionManager: initializing transfer 19899544
[1001] Feb. 01 21:13:09 [Debug] General : AsProtocol job AsProtocolJob(0x11d0538) , sending request AsProtocolTransfer(0x12fa490) , transfer id 19899544
[1001] Feb. 01 21:13:09 [Debug] Network : QtConnectionManager: starting transfer 19899544
[1001] Feb. 01 21:13:09 [Debug] Network : QtConnectionManager: connected, starting transfer immediately
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : start attempt 1 of 1 , timeout 600 sec
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : POST https://xx.xx
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : hdr => Connection : Keep-Alive
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : hdr => Authorization : <skipped>
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : hdr => Content-Length : 1057612
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : hdr => Content-Type : message/rfc822
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : hdr => MS-ASProtocolVersion : 12.1
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : hdr => User-Agent : SailfishOS/1.0-EAS-0.7.51
[1001] Feb. 01 21:13:09 [Debug] Network : Transfer 19899544 : data => 1057612 bytes
[1001] Feb. 01 21:13:10 [Debug] Network : Databuffer:
[1001] Feb. 01 21:13:10 [Debug] General : AsProtocol transfer AsProtocolTransfer(0x12fa490) started
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : started, reply = QNetworkReplyHttpImpl(0x1453600)
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : upload progress 16384 of 1057612
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : upload progress 65536 of 1057612
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : upload progress 180224 of 1057612
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : upload progress 344064 of 1057612
[1001] Feb. 01 21:13:10 [Debug] General : always-on: starting ping in account 4 with 0 suspicious folders
[1001] Feb. 01 21:13:10 [Debug] Storage : MfeStorage: 0 folders from account 4 (client-ids "'191'" ) found in cache, cache size = 1
[1001] Feb. 01 21:13:10 [Debug] Storage : Table: "folderscustom"
[1001] Feb. 01 21:13:10 [Debug] Storage : -1 records found
[1001] Feb. 01 21:13:10 [Debug] Storage : found folder (id = 294 , accountid = 4 , serverid = "Fdefault0/INBOX" , clientid = "191" , synckey = "xx" )
[1001] Feb. 01 21:13:10 [Debug] Storage : 1 folders found
[1001] Feb. 01 21:13:10 [Debug] Storage : MfeStorage: 1 folders from account 4 (types "2" ) found in cache, cache size = 2
[1001] Feb. 01 21:13:10 [Debug] Storage : 0 folders found
[1001] Feb. 01 21:13:10 [Debug] Storage : MfeStorage: 1 folders from account 4 (classes "3,2" ) found in cache, cache size = 2
[1001] Feb. 01 21:13:10 [Debug] Storage : Table: "folderscustom"
[1001] Feb. 01 21:13:10 [Debug] Storage : -1 records found
[1001] Feb. 01 21:13:10 [Debug] Storage : found folder (id = 274 , accountid = 4 , serverid = "F30" , clientid = "fb2df593-07bd-488f-82ed-e412836fd5a0" , synckey = "xx" )
[1001] Feb. 01 21:13:10 [Debug] Storage : 1 folders found
[1001] Feb. 01 21:13:10 [Debug] General : always-on: 3 of 3 folders will be pinged in account 4
[1001] Feb. 01 21:13:10 [Debug] General : Job Job(0x1351ca0) created
[1001] Feb. 01 21:13:10 [Debug] General : Starting job JobPing(0x1351ca0)
[1001] Feb. 01 21:13:10 [Debug] General : Job JobPing(0x1351ca0) has been started
[1001] Feb. 01 21:13:10 [Debug] General : Job JobPing(0x1351ca0) (protocol) started in account 4
[1001] Feb. 01 21:13:10 [Debug] General : Account 4 : protocol action factory requested
[1001] Feb. 01 21:13:10 [Debug] General : Account 4 : protocol action factory already exists
[1001] Feb. 01 21:13:10 [Debug] General : Account 4 : emitting factory available signal
[1001] Feb. 01 21:13:10 [Debug] General : Job JobPing(0x1351ca0) (protocol): ActionFactory requested successfully, waiting for response
[1001] Feb. 01 21:13:10 [Debug] General : Job JobPing(0x1351ca0) (protocol): received ActionFactory response, status 200
[1001] Feb. 01 21:13:10 [Debug] General : Job JobPing(0x1351ca0) (protocol): ready for executing protocol actions
[1001] Feb. 01 21:13:10 [Debug] General : Job JobPing(0x1351ca0) (Ping): starting Ping action for account 4
[1001] Feb. 01 21:13:10 [Debug] General : Job Job(0x1462d48) created
[1001] Feb. 01 21:13:10 [Debug] General : Starting job AsProtocolJob(0x1462d48)
[1001] Feb. 01 21:13:10 [Debug] General : AsProtocol job AsProtocolJob(0x1462d48) , about to send a request
[1001] Feb. 01 21:13:10 [Debug] AS_LIB : Ping: 3 folders will be monitored
[1001] Feb. 01 21:13:10 [Debug] AS_LIB : Creating request for command Ping
[1001] Feb. 01 21:13:10 [Debug] Network : QtConnectionManager: initializing transfer 19681888
[1001] Feb. 01 21:13:10 [Debug] General : AsProtocol job AsProtocolJob(0x1462d48) , sending request AsProtocolTransfer(0x12c5258) , transfer id 19681888
[1001] Feb. 01 21:13:10 [Debug] Network : QtConnectionManager: starting transfer 19681888
[1001] Feb. 01 21:13:10 [Debug] Network : QtConnectionManager: connected, starting transfer immediately
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : start attempt 1 of 1 , timeout 2040 sec
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : POST https://xx.xx
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : hdr => Connection : Keep-Alive
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : hdr => Authorization : <skipped>
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : hdr => Content-Length : 90
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : hdr => Content-Type : application/vnd.ms-sync.wbxml
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : hdr => MS-ASProtocolVersion : 12.1
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : hdr => User-Agent : SailfishOS/1.0-EAS-0.7.51
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : data => 90 bytes
[1001] Feb. 01 21:13:10 [Debug] Network : Databuffer: xx
[1001] Feb. 01 21:13:10 [Debug] General : AsProtocol transfer AsProtocolTransfer(0x12c5258) started
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19681888 : started, reply = QNetworkReplyHttpImpl(0x141a710)
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : upload progress 524288 of 1057612
[1001] Feb. 01 21:13:10 [Debug] Network : Transfer 19899544 : upload progress 704512 of 1057612
[1001] Feb. 01 21:13:11 [Debug] Network : Transfer 19899544 : upload progress 933888 of 1057612
[1001] Feb. 01 21:13:11 [Debug] Network : Transfer 19899544 : upload progress 1057612 of 1057612
[1001] Feb. 01 21:13:11 [Debug] Network : Transfer 19681888 : upload progress 90 of 90
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : download progress 0 of 0
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : upload progress 0 of 0
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : finished, reply = QNetworkReplyHttpImpl(0x1453600) , sender = QNetworkReplyHttpImpl(0x1453600)
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : completed, reply = QNetworkReplyHttpImpl(0x1453600)
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : network operation finished with http status 503 "Service Unavailable"
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Date : Sat, 01 Feb 2014 20:13:11 GMT
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Server : grizzly/2.2.22
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Pragma : no-cache
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Content-Length : 0
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Set-Cookie : JSESSIONID=xx; Expires=Sat, 08-Feb-2014 20:13:10 GMT; Path=/; Secure; HttpOnly
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Connection : close
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : hdr <= Content-Type : text/plain
[1001] Feb. 01 21:13:13 [Debug] Network : Transfer 19899544 : data <= 0 bytes
[1001] Feb. 01 21:13:13 [Warning] Transfer 19899544 : http 503 status detected, waiting for 3 seconds before retry
[1001] Feb. 01 21:13:16 [Warning] Transfer 19899544 : retrying to recover from error 503
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : start attempt 1 of 1 , timeout 600 sec
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : POST https://xx.xx
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : hdr => Connection : Keep-Alive
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : hdr => Authorization : <skipped>
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : hdr => Content-Length : 1057612
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : hdr => Content-Type : message/rfc822
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : hdr => MS-ASProtocolVersion : 12.1
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : hdr => User-Agent : SailfishOS/1.0-EAS-0.7.51
[1001] Feb. 01 21:13:16 [Debug] Network : Transfer 19899544 : data => 1057612 bytes
[1001] Feb. 01 21:13:16 [Debug] Network : Databuffer: xx
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : upload progress 0 of 0
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : finished, reply = QNetworkReplyHttpImpl(0x1459c98) , sender = QNetworkReplyHttpImpl(0x1459c98)
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : completed, reply = QNetworkReplyHttpImpl(0x1459c98)
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : network operation finished with http status 503 "Service Unavailable"
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Date : Sat, 01 Feb 2014 20:13:33 GMT
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Server : grizzly/2.2.22
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Pragma : no-cache
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Content-Length : 0
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Set-Cookie : JSESSIONID=xx; Expires=Sat, 08-Feb-2014 20:13:32 GMT; Path=/; Secure; HttpOnly
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Connection : close
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : hdr <= Content-Type : text/plain
[1001] Feb. 01 21:13:34 [Debug] Network : Transfer 19899544 : data <= 0 bytes
[1001] Feb. 01 21:13:34 [Warning] Transfer 19899544 : http 503 status detected, waiting for 90 seconds before retry
[1001] Feb. 01 21:13:41 [Debug] identityimpl.cpp 103 updateState Updating state: NeedsRegistration
[1001] Feb. 01 21:15:19 [Warning] Transfer 19899544 : retrying to recover from error 503
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : start attempt 1 of 1 , timeout 600 sec
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : POST https://xx.xx
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : hdr => Connection : Keep-Alive
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : hdr => Authorization : <skipped>
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : hdr => Content-Length : 1057612
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : hdr => Content-Type : message/rfc822
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : hdr => MS-ASProtocolVersion : 12.1
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : hdr => User-Agent : SailfishOS/1.0-EAS-0.7.51
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : data => 1057612 bytes
[1001] Feb. 01 21:15:19 [Debug] Network : Databuffer: xx
[1001] Feb. 01 21:15:19 [Debug] General : AsProtocol transfer AsProtocolTransfer(0x12fa490) started
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : started, reply = QNetworkReplyHttpImpl(0x143de90)
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : upload progress 16384 of 1057612
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : upload progress 147456 of 1057612
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : upload progress 311296 of 1057612
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : upload progress 393216 of 1057612
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : upload progress 458752 of 1057612
[1001] Feb. 01 21:15:19 [Debug] Network : Transfer 19899544 : upload progress 622592 of 1057612
[1001] Feb. 01 21:15:20 [Debug] Network : Transfer 19899544 : upload progress 688128 of 1057612
[1001] Feb. 01 21:15:20 [Debug] Network : Transfer 19899544 : upload progress 901120 of 1057612
[1001] Feb. 01 21:15:20 [Debug] Network : Transfer 19899544 : upload progress 1057612 of 1057612
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : download progress 0 of 0
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : upload progress 0 of 0
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : finished, reply = QNetworkReplyHttpImpl(0x143de90) , sender = QNetworkReplyHttpImpl(0x143de90)
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : completed, reply = QNetworkReplyHttpImpl(0x143de90)
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : network operation finished with http status 503 "Service Unavailable"
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Date : Sat, 01 Feb 2014 20:15:20 GMT
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Server : grizzly/2.2.22
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Pragma : no-cache
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Content-Length : 0
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Set-Cookie : JSESSIONID=xx; Expires=Sat, 08-Feb-2014 20:15:19 GMT; Path=/; Secure; HttpOnly
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Connection : close
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : hdr <= Content-Type : text/plain
[1001] Feb. 01 21:15:21 [Debug] Network : Transfer 19899544 : data <= 0 bytes
[1001] Feb. 01 21:15:21 [Warning] Transfer 19899544 : http 503 status detected, waiting for 450 seconds before retry
Does you service provider supports sending attaching of this size ? Connection seems to be closed in the middle of the sending.
VDVsx ( 2014-02-03 10:36:25 +0200 )editMy provider has a 35 MB limit on attachments. Yesterday I was trying to send a text-only email, it failed to send (There were no other emails in the outbox). Syncing again via cover didn't help. Occasionally some mails can be send.
maurice_moss ( 2014-02-03 12:10:46 +0200 )editOk, might be some problem with Open Xchange, will check if can be reproduced.
VDVsx ( 2014-02-03 17:05:24 +0200 )editI noticed that if Emails have the size 2048 or 3072 bytes they can't be sent, they will stay in the outbox forever and sync errors will appear. It doesn't happen all the time, though, most Emails can be send.
maurice_moss ( 2014-04-21 22:02:45 +0200 )edit