A NOTE has been added to this issue.
======================================================================
http://www.dbmail.org/mantis/view.php?id=392
======================================================================
Reported By: jasb
Assigned To:
======================================================================
Project: DBMail
Issue ID: 392
Category: IMAP daemon
Reproducibility: sometimes
Severity: major
Priority: normal
Status: new
target:
======================================================================
Date Submitted: 08-Aug-06 10:59 CEST
Last Modified: 17-Aug-06 16:45 CEST
======================================================================
Summary: Copying messages to "Sent Items"
Description:
When i send an email, and then outlook express is going to copy the message
to the "sent items" i get this error:
This is a trace_level=1, when i can catch a trace_level=5 i'll past it
here.
Before and inclusive 2.1.6 this never happen.
Aug 8 09:55:53 lira postfix/smtpd[30043]: disconnect from
localhost.localdomain[127.0.0.1]
Aug 8 09:55:53 lira dbmail/imap4d[14805]: Error
dbmail-imapsession.c,build_args_array_ext: timeout occurred in fgetc. last
char [ ]
Aug 8 09:55:53 lira dbmail/imap4d[14805]: Error
imap4.c,IMAPClientHandler: error reading extra command info
======================================================================
----------------------------------------------------------------------
jasb - 09-Aug-06 15:22
----------------------------------------------------------------------
I Don't know how to edit the "Aditional Information" grrr dumb me.
Ok.. this is the best i can get, this is a trace_level=5
I also noticed things like this, that i don't think it is normal (correct
me if so)
the "j7zu" text should be here? "Info COMMAND: [j7zu APPEND"
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info COMMAND: [j7zu APPEND
"Sent Items" (\Seen) " 9-Aug-2006 13:48:24 +0100" {96174}]
So, basic what i did was, wrote a message, and then clicked send.
And the message wasn't copied to the sent folder because of this error,
still don't when this happens, but itsn't always..
Like i said, this only started to happen after 2.1.6 version more or less,
before that never happened.
Any thing else you need just ask (By email if you can 'cause i may forget
to came here to check).
-----------
### fgetc error ###
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Message
serverchild.c,PerformChildTask: incoming connection from [192.168.1.3] by
pid [16518]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug
serverchild.c,PerformChildTask: client info init complete, calling client
handler
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug RESPONSE: [* OK dbmail
imap (protocol version 4r1) server 2.1 ready to run^M ]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info COMMAND: [egm5 CAPABILITY]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info imap4.c,IMAPClientHandler:
Executing command capability...
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug RESPONSE: [* CAPABILITY
IMAP4 IMAP4rev1 AUTH=LOGIN ACL NAMESPACE CHILDREN SORT QUOTA^M ]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug RESPONSE: [egm5 OK
CAPABILITY completed^M ]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info imap4.c,IMAPClientHandler:
Finished command capability [0]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info COMMAND: [bvle LOGIN
"[EMAIL PROTECTED]" "pass"]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug arg[0]: '[EMAIL PROTECTED]'
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug arg[1]: 'pass'
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info imap4.c,IMAPClientHandler:
Executing command login...
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug
dbmail-imapsession.c,dbmail_imap_session_handle_auth: trying to validate
user [EMAIL PROTECTED], pass [XXXX]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug db.c,db_usermap_resolve:
checking userid '[EMAIL PROTECTED]' in usermap
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug db.c,db_usermap_resolve:
client on inet socket [inet:192.168.1.222:143]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug dbmysql.c,db_query: query
[SELECT login, sock_allow, sock_deny, userid FROM dbmail_usermap WHERE
login in ('[EMAIL PROTECTED]','ANY') ORDER BY sock_allow, sock_deny]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug db.c,db_usermap_resolve:
login '[EMAIL PROTECTED]' not found in usermap
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug dbmysql.c,db_query: query
[SELECT user_idnr FROM dbmail_users WHERE lower(userid) =
lower('[EMAIL PROTECTED]')]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug dbmysql.c,db_query: query
[SELECT user_idnr, passwd, encryption_type FROM dbmail_users WHERE
user_idnr = '235']
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug authsql.c,auth_validate:
validating using plaintext passwords
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug dbmysql.c,db_query: query
[UPDATE dbmail_users SET last_login = '2006-08-09 13:52:43' WHERE user_idnr
= '235']
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Message
dbmail-imapsession.c,dbmail_imap_session_handle_auth: user (id:235, name
[EMAIL PROTECTED]) tries login
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Message
dbmail-imapsession.c,dbmail_imap_session_handle_auth: user (id 235, name
[EMAIL PROTECTED]) login accepted @ 2006-08-09 13:52:43
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug RESPONSE: [bvle OK LOGIN
completed^M ]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info imap4.c,IMAPClientHandler:
Finished command login [0]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info COMMAND: [j7zu APPEND
"Sent Items" (\Seen) " 9-Aug-2006 13:48:24 +0100" {96174}]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug
dbmail-imapsession.c,build_args_array_ext: last char = }
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Error
dbmail-imapsession.c,build_args_array_ext: timeout occurred in fgetc. last
char [ ]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Error
dbmail-imapsession.c,dbmail_imap_session_printf: client socket closed
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug
serverchild.c,PerformChildTask: client handling complete, closing streams
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info
serverchild.c,PerformChildTask: connection closed
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info
serverchild.c,PerformChildTask: waiting for connection
### fgetc error ###
### something else i saw in the log with error ###
Aug 9 13:36:43 lira dbmail/imap4d[16518]: Error
dbmail-imapsession.c,dbmail_imap_session_readln: error reading from
client
Aug 9 13:36:43 lira dbmail/imap4d[16518]: Error
imap4.c,IMAPClientHandler: error reading command -- bailing out
Aug 9 13:36:43 lira dbmail/imap4d[16518]: Debug RESPONSE: [* BYE error
reading command^M ]
Aug 9 13:36:43 lira dbmail/imap4d[16518]: Debug
serverchild.c,PerformChildTask: client handling complete, closing streams
Aug 9 13:36:43 lira dbmail/imap4d[16518]: Info
serverchild.c,PerformChildTask: connection closed
Aug 9 13:36:43 lira dbmail/imap4d[16518]: Info
serverchild.c,PerformChildTask: waiting for connection
### something else i saw in the log with error ###
-----------
----------------------------------------------------------------------
paul - 17-Aug-06 16:15
----------------------------------------------------------------------
I'm kinda suspicious about the timedelta here:
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Info COMMAND: [j7zu APPEND "Sent
Items" (\Seen) " 9-Aug-2006 13:48:24 +0100" {96174}]
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Debug
dbmail-imapsession.c,build_args_array_ext: last char = }
Aug 9 13:52:43 lira dbmail/imap4d[16518]: Error
dbmail-imapsession.c,build_args_array_ext: timeout occurred in fgetc. last
char [ ]
so according to syslog there's no time difference between de command and
the timeout.
I'm adding some additional info to the timeout error message, add some
needed error checking, plus allow uploads of large messages over slow
lines.
Jorge, plz test rev 2226
----------------------------------------------------------------------
jasb - 17-Aug-06 16:45
----------------------------------------------------------------------
Paul,
2226 updated, i'll set a trace_level=5 for imapd and i'll let you know
when i'll have some news about it.
Issue History
Date Modified Username Field Change
======================================================================
08-Aug-06 10:59 jasb New Issue
09-Aug-06 15:01 jasb Issue Monitored: jasb
09-Aug-06 15:22 jasb Note Added: 0001334
17-Aug-06 16:15 paul Note Added: 0001345
17-Aug-06 16:45 jasb Note Added: 0001346
======================================================================
