A NOTE has been added to this issue.
======================================================================
http://www.dbmail.org/mantis/view.php?id=392
======================================================================
Reported By: jasb
Assigned To: paul
======================================================================
Project: DBMail
Issue ID: 392
Category: IMAP daemon
Reproducibility: sometimes
Severity: major
Priority: normal
Status: assigned
target:
======================================================================
Date Submitted: 08-Aug-06 10:59 CEST
Last Modified: 03-Sep-06 09:59 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.
----------------------------------------------------------------------
jasb - 18-Aug-06 01:37
----------------------------------------------------------------------
Paul,
So it happened again and i have the trace_level=5 to catch a debuging
information with the svn 2226 like you asked, and here it is, with more
info than the last time.
Do you want the raw message of it has nothing to do with the message it
self?
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Info COMMAND: [ybg5 LOGIN
"[EMAIL PROTECTED]" "mypasswd"]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug arg[0]:
'[EMAIL PROTECTED]'
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug arg[1]: 'mypasswd'
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Info imap4.c,IMAPClientHandler:
Executing command login...
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug
dbmail-imapsession.c,dbmail_imap_session_handle_auth: trying to validate
user [EMAIL PROTECTED], pass [XXXX]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug db.c,db_usermap_resolve:
checking userid '[EMAIL PROTECTED]' in usermap
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug db.c,db_usermap_resolve:
client on inet socket [inet:195.27.118.71:143]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: 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 18 00:26:29 lira dbmail/imap4d[3440]: Debug db.c,db_usermap_resolve:
login '[EMAIL PROTECTED]' not found in usermap
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug dbmysql.c,db_query: query
[SELECT user_idnr FROM dbmail_users WHERE lower(userid) =
lower('[EMAIL PROTECTED]')]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug dbmysql.c,db_query: query
[SELECT user_idnr, passwd, encryption_type FROM dbmail_users WHERE
user_idnr = '235']
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug authsql.c,auth_validate:
validating using plaintext passwords
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug dbmysql.c,db_query: query
[UPDATE dbmail_users SET last_login = '2006-08-18 00:26:29' WHERE
user_idnr = '235']
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Message
dbmail-imapsession.c,dbmail_imap_session_handle_auth: user (id:235, name
[EMAIL PROTECTED]) tries login
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Message
dbmail-imapsession.c,dbmail_imap_session_handle_auth: user (id 235, name
[EMAIL PROTECTED]) login accepted @ 2006-08-18 00:26:29
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug RESPONSE: [ybg5 OK LOGIN
completed^M ]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Info imap4.c,IMAPClientHandler:
Finished command login [0]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Info COMMAND: [qrx0 APPEND "Sent
Items" (\Seen) "18-Aug-2006 00:23:45 +0100" {1220}]
Aug 18 00:26:29 lira dbmail/imap4d[3440]: Debug
dbmail-imapsession.c,build_args_array_ext:last char = }
Aug 18 00:26:30 lira dbmail/imap4d[3440]: Error
dbmail-imapsession.c,build_args_array_ext:timeout occurred in fgetc; last
char [ ] at dataidx [1183]; timeout [4000]
Aug 18 00:26:30 lira dbmail/imap4d[3440]: Error imap4.c,IMAPClientHandler:
error reading extra command info
Aug 18 00:26:30 lira dbmail/imap4d[3440]: Debug
serverchild.c,PerformChildTask: client handling complete, closing streams
Aug 18 00:26:30 lira dbmail/imap4d[3440]: Info
serverchild.c,PerformChildTask: connection closed
Aug 18 00:26:30 lira dbmail/imap4d[3440]: Info
serverchild.c,PerformChildTask: waiting forconnection
----------------------------------------------------------------------
paul - 18-Aug-06 15:30
----------------------------------------------------------------------
Jorge,
Plz upgrade to 2227 and repost the debug logs. I've got a pretty good idea
what might be going on here, but I need confirmation from your logs. I've
only changed the error/debug message after the timeout.
----------------------------------------------------------------------
jasb - 18-Aug-06 17:09
----------------------------------------------------------------------
Ok Paul,
Done, and when i'll have another error i'll post them here.
Meanwhile in the make time, there's some warnings (that almost for sure
don't have nothing to do with it, but if you want to kill this warnings
it'll be good :P)
## warning %1
gcc -DHAVE_CONFIG_H -I. -I. -I. -I. -g -O2 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -I/usr/include/gmime-2.0
-I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include -W -Wall
-Wpointer-arith -Wstrict-prototypes -MT libdbmail_la-debug.lo -MD -MP -MF
.deps/libdbmail_la-debug.Tpo -c debug.c -fPIC -DPIC -o
.libs/libdbmail_la-debug.o
debug.c: In function 'newtrace':
debug.c:74: warning: unused parameter 'module'
debug.c:75: warning: unused parameter 'file'
debug.c:75: warning: unused parameter 'function'
if /bin/sh ./libtool --tag=CC --mode=compile gcc -DHAVE_CONFIG_H -I. -I.
-I. -I. -g -O2 -I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include
-I/usr/include/gmime-2.0 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -W -Wall -Wpointer-arith -Wstrict-prototypes
-MT libdbmail_la-list.lo -MD -MP -MF ".deps/libdbmail_la-list.Tpo" -c -o
libdbmail_la-list.lo `test -f 'list.c' || echo './'`list.c; \
then mv -f ".deps/libdbmail_la-list.Tpo"
".deps/libdbmail_la-list.Plo"; else rm -f ".deps/libdbmail_la-list.Tpo";
exit 1; fi
## warning %2
gcc -DHAVE_CONFIG_H -I. -I. -I. -I. -g -O2 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -I/usr/include/gmime-2.0
-I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include -W -Wall
-Wpointer-arith -Wstrict-prototypes -MT libdbmail_la-pipe.lo -MD -MP -MF
.deps/libdbmail_la-pipe.Tpo -c pipe.c -fPIC -DPIC -o
.libs/libdbmail_la-pipe.o
pipe.c: In function 'send_mail':
pipe.c:145: warning: pointer targets in passing argument 1 of
'g_mime_utils_header_encode_phrase' differ in signedness
pipe.c:146: warning: pointer targets in passing argument 1 of
'g_mime_utils_header_encode_phrase' differ in signedness
pipe.c:147: warning: pointer targets in passing argument 1 of
'g_mime_utils_header_encode_text' differ in signedness
if /bin/sh ./libtool --tag=CC --mode=compile gcc -DHAVE_CONFIG_H -I. -I.
-I. -I. -g -O2 -I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include
-I/usr/include/gmime-2.0 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -W -Wall -Wpointer-arith -Wstrict-prototypes
-MT libdbmail_la-dsn.lo -MD -MP -MF ".deps/libdbmail_la-dsn.Tpo" -c -o
libdbmail_la-dsn.lo `test -f 'dsn.c' || echo './'`dsn.c; \
then mv -f ".deps/libdbmail_la-dsn.Tpo"
".deps/libdbmail_la-dsn.Plo"; else rm -f ".deps/libdbmail_la-dsn.Tpo";
exit 1; fi
## warning %3
if gcc -DHAVE_CONFIG_H -I. -I. -I. -I. -g -O2 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -I/usr/include/gmime-2.0
-I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include -W -Wall
-Wpointer-arith -Wstrict-prototypes -MT dbmail-imapsession.o -MD -MP -MF
".deps/dbmail-imapsession.Tpo" -c -o dbmail-imapsession.o
dbmail-imapsession.c; \
then mv -f ".deps/dbmail-imapsession.Tpo"
".deps/dbmail-imapsession.Po"; else rm -f ".deps/dbmail-imapsession.Tpo";
exit 1; fi
dbmail-imapsession.c: In function 'dbmail_imap_session_prompt':
dbmail-imapsession.c:1254: warning: pointer targets in passing argument 1
of 'base64_encode' differ in signedness
dbmail-imapsession.c:1254: warning: pointer targets in passing argument 2
of 'base64_encode' differ in signedness
/bin/sh ./libtool --tag=CC --mode=link gcc -g -O2 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -I/usr/include/gmime-2.0
-I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include -W -Wall
-Wpointer-arith -Wstrict-prototypes -Wl,--export-dynamic -lcrypt
-lglib-2.0 -lgmime-2.0 -lz -lnsl -lgobject-2.0 -lglib-2.0 -o
dbmail-imapd quota.o imap4.o dm_imaputil.o imapcommands.o memblock.o
imapd.o dbmail-imapsession.o libdbmail.la
gcc -g -O2 -I/usr/include/glib-2.0 -I/usr/lib/glib-2.0/include
-I/usr/include/gmime-2.0 -I/usr/include/glib-2.0
-I/usr/lib/glib-2.0/include -W -Wall -Wpointer-arith -Wstrict-prototypes
-Wl,--export-dynamic -o .libs/dbmail-imapd quota.o imap4.o dm_imaputil.o
imapcommands.o memblock.o imapd.o dbmail-imapsession.o -lcrypt
/usr/lib/libgmime-2.0.so -lz -lnsl /usr/lib/libgobject-2.0.so
/usr/lib/libglib-2.0.so ./.libs/libdbmail.so -Wl,--rpath
-Wl,/usr/local/lib
creating dbmail-imapd
----------------------------------------------------------------------
aaron - 18-Aug-06 17:51
----------------------------------------------------------------------
Nope, please don't do that. Open a new bug or post these to the mailing
list. One bug report per bug. This bug report is about Sent Items!
----------------------------------------------------------------------
jasb - 18-Aug-06 17:57
----------------------------------------------------------------------
:D
Ok Aaron, i'm going to do that heeh
sorry :P
Jorge
----------------------------------------------------------------------
jasb - 18-Aug-06 18:41
----------------------------------------------------------------------
It still didn't happened that problem with the "fgetc" but i noticed
something else that i think that is related to this:
See below:
Does this info's important for this bug Paul?
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Debug
dbmail-imapsession.c,_imap_cache_update: cache size
[14652292]
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Debug RESPONSE: [ ]
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Debug RESPONSE: [BODY[]
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Debug RESPONSE: [HEADER]
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Debug RESPONSE: [] {1481}^M ]
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Error
dbmail-imapsession.c,dbmail_imap_session_printf: wri
te to client socket failed
Aug 18 17:20:48 lira last message repeated 8 times
Aug 18 17:20:48 lira dbmail/imap4d[3261]: Debug
dbmail-imapsession.c,_imap_show_body_section: itemty
pe [1] partspec []
----------------------------------------------------------------------
jasb - 19-Aug-06 14:11
----------------------------------------------------------------------
Paul, with svn 2227 there's the error, does it help?
Anything you need just say
Take a look.
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Message
serverchild.c,PerformChildTask: incoming connection from [84.91.33.25] by
pid [3271]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug
serverchild.c,PerformChildTask: client info init complete, calling client
handler
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug RESPONSE: [* OK dbmail
imap (protocol version 4r1) server 2.1 ready to run^M ]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info COMMAND: [pr0q CAPABILITY]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info imap4.c,IMAPClientHandler:
Executing command capability...
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug RESPONSE: [* CAPABILITY
IMAP4 IMAP4rev1 AUTH=LOGIN ACL NAMESPACE CHILDREN SORT QUOTA^M ]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug RESPONSE: [pr0q OK
CAPABILITY completed^M ]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info imap4.c,IMAPClientHandler:
Finished command capability [0]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info COMMAND: [bosv LOGIN
"[EMAIL PROTECTED]" "XXX"]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug arg[0]: '[EMAIL PROTECTED]'
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug arg[1]: 'XXX'
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info imap4.c,IMAPClientHandler:
Executing command login...
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug
dbmail-imapsession.c,dbmail_imap_session_handle_auth: trying to validate
user [EMAIL PROTECTED], pass [XXXX]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug db.c,db_usermap_resolve:
checking userid '[EMAIL PROTECTED]' in usermap
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug db.c,db_usermap_resolve:
client on inet socket [inet:195.23.114.76:143]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: 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 19 13:04:51 lira dbmail/imap4d[3271]: Debug db.c,db_usermap_resolve:
login '[EMAIL PROTECTED]' not found in usermap
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug dbmysql.c,db_query: query
[SELECT user_idnr FROM dbmail_users WHERE lower(userid) =
lower('[EMAIL PROTECTED]')]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug dbmysql.c,db_query: query
[SELECT user_idnr, passwd, encryption_type FROM dbmail_users WHERE
user_idnr = '235']
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug authsql.c,auth_validate:
validating using plaintext passwords
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug dbmysql.c,db_query: query
[UPDATE dbmail_users SET last_login = '2006-08-19 13:04:51' WHERE
user_idnr = '235']
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Message
dbmail-imapsession.c,dbmail_imap_session_handle_auth: user (id:235, name
[EMAIL PROTECTED]) tries login
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Message
dbmail-imapsession.c,dbmail_imap_session_handle_auth: user (id 235, name
[EMAIL PROTECTED]) login accepted @ 2006-08-19 13:04:51
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug RESPONSE: [bosv OK LOGIN
completed^M ]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info imap4.c,IMAPClientHandler:
Finished command login [0]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info COMMAND: [88pl APPEND "Sent
Items" (\Seen) "19-Aug-2006 13:02:45 +0100" {1123}]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug
dbmail-imapsession.c,build_args_array_ext: last char = }
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Error
dbmail-imapsession.c,build_args_array_ext: timeout occurred in fgetc; got
[1123] of [1123]; timeout [4000]
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Error imap4.c,IMAPClientHandler:
error reading extra command info
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Debug
serverchild.c,PerformChildTask: client handling complete, closing streams
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info
serverchild.c,PerformChildTask: connection closed
Aug 19 13:04:51 lira dbmail/imap4d[3271]: Info
serverchild.c,PerformChildTask: waiting for connection
----------------------------------------------------------------------
jasb - 19-Aug-06 23:15
----------------------------------------------------------------------
Some more info, this is a trace_level=1 but you can see the important info
Aug 19 22:12:44 lira dbmail/imap4d[22735]: Error
dbmail-imapsession.c,build_args
_array_ext: timeout occurred in fgetc; got [15833] of [15833]; timeout
[4000]
Aug 19 22:12:44 lira dbmail/imap4d[22735]: Error
imap4.c,IMAPClientHandler: erro
r reading extra command info
----------------------------------------------------------------------
paul - 20-Aug-06 11:20
----------------------------------------------------------------------
So apparently the timeout is triggered even though we have all needed data.
I'm committing a fix in rev. 2228. I'm not at all sure though *why* the
alarm handler is being called. The timeout used in the example is long
(4000 seconds) and is apparently not being used up. But then, we should
handle such timeouts more gracefully anyway.
----------------------------------------------------------------------
jasb - 20-Aug-06 11:44
----------------------------------------------------------------------
Updated to 2228.
Anything i'll let you know.
Thanks Paul
----------------------------------------------------------------------
jasb - 23-Aug-06 22:58
----------------------------------------------------------------------
Hi Paul,
I'm just curius, what does this "new assignment", "assign to Paul" means?
----------------------------------------------------------------------
paul - 03-Sep-06 09:59
----------------------------------------------------------------------
Jorge, can I close this bug?
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
18-Aug-06 01:37 jasb Note Added: 0001347
18-Aug-06 15:30 paul Note Added: 0001348
18-Aug-06 17:09 jasb Note Added: 0001349
18-Aug-06 17:51 aaron Note Added: 0001350
18-Aug-06 17:57 jasb Note Added: 0001351
18-Aug-06 18:41 jasb Note Added: 0001352
19-Aug-06 14:11 jasb Note Added: 0001353
19-Aug-06 23:15 jasb Note Added: 0001355
20-Aug-06 11:20 paul Note Added: 0001356
20-Aug-06 11:20 paul Resolution open => fixed
20-Aug-06 11:20 paul Fixed in Version => 2.1.8
20-Aug-06 11:44 jasb Note Added: 0001357
23-Aug-06 22:44 paul Status new => assigned
23-Aug-06 22:44 paul Assigned To => paul
23-Aug-06 22:58 jasb Note Added: 0001369
03-Sep-06 09:59 paul Note Added: 0001379
======================================================================
