A BUGNOTE has been added to this bug. ====================================================================== http://www.dbmail.org/mantis/bug_view_advanced_page.php?bug_id=0000221 ====================================================================== Reported By: xing Assigned To: ====================================================================== Project: DBMail Bug ID: 221 Category: POP3 daemon Reproducibility: always Severity: feature Priority: normal Status: new ====================================================================== Date Submitted: 21-Jun-05 16:44 CEST Last Modified: 21-Jun-05 21:41 CEST ====================================================================== Summary: POP3 daemon can't connect to mysql but dbmail-smtp injects emails fine.. Description: After upgrading to 2.1.1, dbmail-smtp injects emails just fine but pop3 and imap daemon both chockes on init. Apparently the init db check fails breaking the startup. Since dbmail-smtp and dbmail-pop3d both use the same config/libraries, not sure why the db check fails.
--here it the trace 5 dump when pop3 daemon is started -- Jun 21 07:39:55 mail dbmail/pop3d[20975]: server.c,dm_socket: socket created Jun 21 07:39:55 mail dbmail/pop3d[20975]: server.c,dm_bind_and_listen: socket bound and listening Jun 21 07:39:55 mail dbmail/pop3d[20975]: server.c,CreateSocket: socket complete Jun 21 07:39:55 mail dbmail/pop3d[20977]: dbmysql.c,db_query: executing query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0] Jun 21 07:39:55 mail dbmail/pop3d[20977]: dbmysql.c,db_query: executing query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0] Jun 21 07:39:55 mail dbmail/pop3d[20978]: pool.c,child_register: register child [20978] Jun 21 07:39:55 mail dbmail/pop3d[20978]: pool.c,child_register: initializing child_state [20978] using slot [0] Jun 21 07:39:55 mail dbmail/pop3d[20978]: serverchild.c,CreateChild: signal handler placed, going to perform task now Jun 21 07:39:55 mail dbmail/pop3d[20978]: serverchild.c,PerformChildTask: waiting for connection Jun 21 07:39:55 mail dbmail/pop3d[20978]: pool.c,child_reg_disconnected: [20978] Jun 21 07:39:55 mail dbmail/pop3d[20979]: pool.c,child_register: register child [20979] Jun 21 07:39:55 mail dbmail/pop3d[20979]: pool.c,child_register: initializing child_state [20979] using slot [1] Jun 21 07:39:55 mail dbmail/pop3d[20979]: serverchild.c,CreateChild: signal handler placed, going to perform task now Jun 21 07:39:55 mail dbmail/pop3d[20979]: serverchild.c,PerformChildTask: waiting for connection Jun 21 07:39:55 mail dbmail/pop3d[20979]: pool.c,child_reg_disconnected: [20979] Jun 21 07:39:55 mail dbmail/pop3d[20980]: pool.c,child_register: register child [20980] Jun 21 07:39:55 mail dbmail/pop3d[20980]: pool.c,child_register: initializing child_state [20980] using slot [2] Jun 21 07:39:55 mail dbmail/pop3d[20980]: serverchild.c,CreateChild: signal handler placed, going to perform task now Jun 21 07:39:55 mail dbmail/pop3d[20980]: serverchild.c,PerformChildTask: waiting for connection Jun 21 07:39:55 mail dbmail/pop3d[20980]: pool.c,child_reg_disconnected: [20980] Jun 21 07:39:55 mail dbmail/pop3d[20981]: pool.c,child_register: register child [20981] Jun 21 07:39:55 mail dbmail/pop3d[20981]: pool.c,child_register: initializing child_state [20981] using slot [3] Jun 21 07:39:55 mail dbmail/pop3d[20981]: serverchild.c,CreateChild: signal handler placed, going to perform task now Jun 21 07:39:55 mail dbmail/pop3d[20981]: serverchild.c,PerformChildTask: waiting for connection Jun 21 07:39:55 mail dbmail/pop3d[20981]: pool.c,child_reg_disconnected: [20981] Jun 21 07:39:55 mail dbmail/pop3d[20982]: pool.c,child_register: register child [20982] Jun 21 07:39:55 mail dbmail/pop3d[20982]: pool.c,child_register: initializing child_state [20982] using slot [4] Jun 21 07:39:55 mail dbmail/pop3d[20982]: serverchild.c,CreateChild: signal handler placed, going to perform task now Jun 21 07:39:55 mail dbmail/pop3d[20982]: serverchild.c,PerformChildTask: waiting for connection Jun 21 07:39:55 mail dbmail/pop3d[20982]: pool.c,child_reg_disconnected: [20982] Jun 21 07:39:55 mail dbmail/pop3d[20977]: server.c,StartServer: starting main service loop Jun 21 07:39:55 mail dbmail/pop3d[20977]: dbmysql.c,db_check_connection: no database connection, trying to establish on. ====================================================================== ---------------------------------------------------------------------- mobrien9279 - 21-Jun-05 18:06 CEST ---------------------------------------------------------------------- I find that LMTPD ALSO Functions persistantly as well as SMTPd but not IMAPD nor POP3D (This is FBSD 5.4 Mysql 4.1.11 DBMAIL 2.1.1 with LDFLAGS added -lpthread and -L/usr/local/include to all Makefiles) NOTE: LMTPD connects to the database and functions normally NOTE: dbmail-imapd version $Revision: 1778 IMAPD tries database connection and waits while keeping children alive NOTE: dbmail-pop3d version $Revision: 1778 POP3D init fails then POP3D starts killing children and goes away as shown below... IMAPD ===== dbmail/imap4d[587]: server.c,dm_socket: socket created dbmail/imap4d[587]: server.c,dm_bind_and_listen: socket bound and listening dbmail/imap4d[587]: server.c,CreateSocket: socket complete dbmail/imap4d[590]: dbmysql.c,db_query: executing query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0] dbmail/imap4d[590]: dbmysql.c,db_query: executing query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0] dbmail/imap4d[610]: pool.c,child_register: register child [610] dbmail/imap4d[610]: pool.c,child_register: initializing child_state [610] using slot [0] dbmail/imap4d[610]: serverchild.c,CreateChild: signal handler placed, going to perform task now dbmail/imap4d[610]: serverchild.c,PerformChildTask: waiting for connection dbmail/imap4d[610]: pool.c,child_reg_disconnected: [610] dbmail/imap4d[614]: pool.c,child_register: register child [614] dbmail/imap4d[614]: pool.c,child_register: initializing child_state [614] using slot [1] dbmail/imap4d[614]: serverchild.c,CreateChild: signal handler placed, going to perform task now dbmail/imap4d[614]: serverchild.c,PerformChildTask: waiting for connection dbmail/imap4d[614]: pool.c,child_reg_disconnected: [614] dbmail/imap4d[617]: pool.c,child_register: register child [617] dbmail/imap4d[617]: pool.c,child_register: initializing child_state [617] using slot [2] dbmail/imap4d[617]: serverchild.c,CreateChild: signal handler placed, going to perform task now dbmail/imap4d[617]: serverchild.c,PerformChildTask: waiting for connection dbmail/imap4d[617]: pool.c,child_reg_disconnected: [617] dbmail/imap4d[623]: pool.c,child_register: register child [623] dbmail/imap4d[623]: pool.c,child_register: initializing child_state [623] using slot [3] dbmail/imap4d[623]: serverchild.c,CreateChild: signal handler placed, going to perform task now dbmail/imap4d[623]: serverchild.c,PerformChildTask: waiting for connection dbmail/imap4d[623]: pool.c,child_reg_disconnected: [623] dbmail/imap4d[631]: pool.c,child_register: register child [631] dbmail/imap4d[631]: pool.c,child_register: initializing child_state [631] using slot [4] dbmail/imap4d[631]: serverchild.c,CreateChild: signal handler placed, going to perform task now dbmail/imap4d[631]: serverchild.c,PerformChildTask: waiting for connection dbmail/imap4d[631]: pool.c,child_reg_disconnected: [631] dbmail/imap4d[637]: pool.c,child_register: register child [637] dbmail/imap4d[637]: pool.c,child_register: initializing child_state [637] using slot [5] dbmail/imap4d[637]: serverchild.c,CreateChild: signal handler placed, going to perform task now dbmail/imap4d[637]: serverchild.c,PerformChildTask: waiting for connection dbmail/imap4d[637]: pool.c,child_reg_disconnected: [637] dbmail/imap4d[642]: pool.c,child_register: register child [642] dbmail/imap4d[642]: pool.c,child_register: initializing child_state [642] using slot [6] etc... POP3d =====dbmail/pop3d[57015]: dbmysql.c,db_check_connection: no database connection, trying to establish on. dbmail/pop3d[57015]: dbmysql.c,db_connect: mysql_real_connect failed: Can't connect to MySQL server on '192.168.100.8' (61) dbmail/pop3d[57015]: dbmysql.c,db_check_connection: unable to connect to database. dbmail/pop3d[57015]: server.c,StartServer: entering sleep-mode until database is back again dbmail/pop3d[57015]: pool.c,manage_stop_children: General stop requested. Killing children.. dbmail/pop3d[57016]: serverchild.c,active_child_sig_handler: got signal [Terminated] dbmail/pop3d[57016]: serverchild.c,active_child_sig_handler: setting stop request dbmail/pop3d[57016]: serverchild.c,PerformChildTask: accept failed dbmail/pop3d[57016]: serverchild.c,PerformChildTask: stop requested dbmail/pop3d[57016]: pool.c,child_reg_disconnected: [57016] dbmail/pop3d[57016]: serverchild.c,disconnect_all: database connection still open, closing dbmail/pop3d[57016]: pool.c,child_unregister: child [57016] unregistered dbmail/pop3d[57015]: server.c,ParentSigHandler: got signal [Child exited] dbmail/pop3d[57015]: pool.c,scoreboard_release: pid [57016] dbmail/pop3d[57017]: serverchild.c,active_child_sig_handler: got signal [Terminated] dbmail/pop3d[57017]: serverchild.c,active_child_sig_handler: setting stop request dbmail/pop3d[57017]: serverchild.c,PerformChildTask: accept failed dbmail/pop3d[57017]: serverchild.c,PerformChildTask: stop requested AND NOTE: with processes all gone attempt restart dbmail/pop3d[598]: server.c,dm_socket: socket created dbmail/pop3d[598]: server.c,dm_bind_and_listen: Address already in use dbmail/pop3d[810]: server.c,dm_socket: socket created dbmail/pop3d[810]: server.c,dm_bind_and_listen: Address already in use ---------------------------------------------------------------------- mobrien9279 - 21-Jun-05 18:41 CEST ---------------------------------------------------------------------- dbmail-util Version: 2.1 $Revision: 1780 works fine, no connection issues dbmail-users Version: 2.1 $Revision: 1780 also connects fine ---------------------------------------------------------------------- paul - 21-Jun-05 21:28 CEST ---------------------------------------------------------------------- Xing, I'm most interested in the lines **right after** your log ends. All daemons share the same framework. The parent process (20977) preforks and goes into a main event-loop which checks the database connection every 10 seconds or so. If the database is down, all preforked children are shutdown until the database comes back; then they are preforked again and we're a happy family of processes. You say dbmail-pop3d chokes, but I see no signs of failure other than a problem with the database connection. I need more info... ---------------------------------------------------------------------- xing - 21-Jun-05 21:41 CEST ---------------------------------------------------------------------- Paul, the "no database connection" is the last log I can get out of the pop3d daemon even after waiting more than 10 seconds for the re-try. Telnet to port 110 gets rejected and I assume the daemon is in the wait/reject mode as you mentioned. Both dbmail-util and dbmail-smtp connect to the db fine and all the new add_* table scripts have been applied. Jun 21 12:37:40 mail dbmail/pop3d[23405]: serverchild.c,PerformChildTask: waiting for connection Jun 21 12:37:40 mail dbmail/pop3d[23405]: pool.c,child_reg_disconnected: [23405] Jun 21 12:37:40 mail dbmail/pop3d[23400]: server.c,StartServer: starting main service loop Jun 21 12:37:40 mail dbmail/pop3d[23400]: dbmysql.c,db_check_connection: no database connection, trying to establish on. Jun 21 12:38:00 mail dbmail/smtp[23464]: dbmail-message.c, sort_and_deliver: message id=2183925, size=3018 is inserted Jun 21 12:38:00 mail postfix/pipe[22263]: E04655E00AE: to=<[EMAIL PROTECTED]>, relay=dbmail, delay=1, status=sent (fanfiction.com) Jun 21 12:38:12 mail dbmail/smtp[23534]: dbmail-message.c, sort_and_deliver: message id=2183927, size=1970 is inserted Jun 21 12:38:12 mail postfix/pipe[22263]: 0795B5E0093: to=<[EMAIL PROTECTED]>, relay=dbmail, delay=1, status=sent (fanfiction.com) Jun 21 12:38:13 mail dbmail/smtp[23538]: dbmail-message.c, sort_and_deliver: message id=2183929, size=3043 is inserted Jun 21 12:38:14 mail postfix/pipe[22263]: E13275E0099: to=<[EMAIL PROTECTED]>, relay=dbmail, delay=1, status=sent (fanfiction.com) Jun 21 12:38:48 mail dbmail/smtp[23653]: dbmail-message.c, sort_and_deliver: message id=2183931, size=3210 is inserted Jun 21 12:38:48 mail postfix/pipe[22263]: BCFE15E0093: to=<[EMAIL PROTECTED]>, relay=dbmail, delay=0, status=sent (fanfiction.net) Jun 21 12:38:51 mail dbmail/smtp[23666]: dbmail-message.c, sort_and_deliver: message id=2183933, size=2921 is inserted Jun 21 12:38:51 mail postfix/pipe[22263]: 05CFD5E0099: to=<[EMAIL PROTECTED]>, relay=dbmail, delay=0, status=sent (fanfiction.com) Nothing happens after pop3d says no db connection and you can see dbmail-smtp works fine. Bug History Date Modified Username Field Change ====================================================================== 21-Jun-05 16:44xing New Bug 21-Jun-05 18:06mobrien9279 Bugnote Added: 0000751 21-Jun-05 18:41mobrien9279 Bugnote Added: 0000752 21-Jun-05 21:28paul Bugnote Added: 0000753 21-Jun-05 21:41xing Bugnote Added: 0000754 ======================================================================
