Paul J Stevens a écrit :
I'm not much interested in postfix traces. I want trace_level=5 dbmail-smtp
traces.
Try to cat such a message straight into dbmail-smtp from the commandline.
Do know how to use gdb? A backtrace would be very useful.
All right. I've attached the two cases: the logs when the I do a
'postfix flush' and the logs of cat'ing the mail directly to
dbmail-smtp, from the command line. It looks like it's not liking the
headers.
As for gdb, I've used it but how should I get the backtrace?
Thanks,
FX.
After a postfix flush, this is what I get in the maillog:
Jun 29 13:59:12 localhost dbmail/smtp[10506]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost dbmail/smtp[10506]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: 3A2AB114B64: from=<[EMAIL
PROTECTED]>, size=2057, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: 3BB9C114B63: from=<[EMAIL
PROTECTED]>, size=22662, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost postfix/pipe[10505]: 21C1B114B61: to=<[EMAIL
PROTECTED]>,relay=dbmail, delay=94527, status=deferred (Command died with
signal 11: "/usr/local/sbin/dbmail-smtp")
Jun 29 13:59:12 localhost dbmail/smtp[10510]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost dbmail/smtp[10510]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: 77E74114B5F: from=<[EMAIL
PROTECTED]>, size=677386, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: D364C114B66: from=<[EMAIL
PROTECTED]>, size=243457, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: D1307114B59: from=<[EMAIL
PROTECTED]>, size=2043, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost dbmail/smtp[10514]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost dbmail/smtp[10514]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: CA547114B62: from=<[EMAIL
PROTECTED]>, size=629039, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost dbmail/smtp[10517]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost postfix/nqmgr[6733]: 53CA7114B60: from=<[EMAIL
PROTECTED]>, size=7376, nrcpt=1 (queue active)
Jun 29 13:59:12 localhost postfix/pipe[10507]: 9420E114B65: to=<[EMAIL
PROTECTED]>,relay=dbmail, delay=76018, status=deferred (Command died with
signal 11: "/usr/local/sbin/dbmail-smtp")
Jun 29 13:59:12 localhost dbmail/smtp[10517]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:12 localhost postfix/pipe[10511]: 945BA114B56: to=<[EMAIL
PROTECTED]>,relay=dbmail, delay=165085, status=deferred (Command died with
signal 11: "/usr/local/sbin/dbmail-smtp")
Jun 29 13:59:13 localhost postfix/nqmgr[6733]: A74A5114B67: from=<[EMAIL
PROTECTED]>, size=679249, nrcpt=1 (queue active)
Jun 29 13:59:13 localhost postfix/pipe[10505]: 3A2AB114B64: to=<[EMAIL
PROTECTED]>,relay=dbmail, delay=82206, status=deferred (Command died with
signal 11: "/usr/local/sbin/dbmail-smtp")
Jun 29 13:59:13 localhost dbmail/smtp[10520]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10520]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10528]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10528]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10530]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10530]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10522]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10522]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10523]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10523]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10524]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10524]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10535]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 13:59:13 localhost dbmail/smtp[10535]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
-----
If I cat the mail directly into dbmail-smtp, from the command line:
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_physmessage LIMIT 1 OFFSET 0]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT 1=1 FROM dbmail_headervalue LIMIT 1 OFFSET 0]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list():
mimelist currently has [0] nodes
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): mail
address parser starting
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): total
fields in header 0
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): found
0 emailaddresses
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): mail
address parser finished
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list():
mimelist currently has [0] nodes
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): mail
address parser starting
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): total
fields in header 0
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): found
0 emailaddresses
Jun 29 14:03:13 localhost dbmail/smtp[10561]: mail_address_build_list(): mail
address parser finished
Jun 29 14:03:13 localhost dbmail/smtp[10561]: main(): no return path found.
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
checking user [EMAIL PROTECTED] in alias table
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
checks [-1]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('[EMAIL
PROTECTED]') AND lower(alias) <> lower(deliver_to)]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
into checking loop
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
checking user [EMAIL PROTECTED] to 3
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
checking user [3] in alias table
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
checks [1]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('3')
AND lower(alias) <> lower(deliver_to)]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: authsql.c,auth_check_user_ext:
adding [3] to deliver_to address
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dsn.c, dsnuser_resolve: user
[EMAIL PROTECTED] found total of [1] aliases
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [BEGIN]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT user_idnr FROM dbmail_users WHERE userid='[EMAIL PROTECTED]@__']
Jun 29 14:03:13 localhost dbmail/smtp[10561]: misc.c,create_unique_id:
created:701816680e98e05978e5c6bf568afa51
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT mailbox_idnr FROM dbmail_mailboxes WHERE name='INBOX' AND
owner_idnr='1']
Jun 29 14:03:13 localhost dbmail/smtp[10561]: db.c, db_find_create_mailbox:
mailbox [INBOX] found
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES ('0',
CURRENT_TIMESTAMP)]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_messages(mailbox_idnr, physmessage_id,
unique_id,recent_flag, status) VALUES ('5', '959',
'701816680e98e05978e5c6bf568afa51', '1', '5')]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '1524']
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_messageblks(is_header, messageblk,blocksize,
physmessage_id)VALUES ('1','X-Invalid-Header: C/ 629039 312
[EMAIL
PROTECTED]"client_name=reserv6.server5.comA^\client_address=193.49.225.20A4message_origin=reserv6.server5.com[193.49.225.20]A
[EMAIL PROTECTED]@myserver.comM^O \n^I629351NNReceived: from
reserv6.server5.com (reserv6.server5.com\n^I[193.49.225.20])N7\n^Iby
mail.myserver.com (Postfix) with ESMTP id CA547114B62N<\n^Ifor <[EMAIL
PROTECTED]>; Tue, 28 Jun 2005 14:41:02 +0200 (CEST)NLReceived:
from\n^Icreinnovsigrid (creinnovsigrid.server5.com [134.206.68.3])NT
by\n^Ireserv6.server5.com (8.13.3/jtpda-5.3.1) with SMTP idj5SCdJXs013548N+
;\n^ITue, 28 Jun 2005 14:39:19 +0200N6Message-ID:\n^I<[EMAIL
PROTECTED]>N,From: \"SIGRID\"\n^I<sigrid.Jun 29 14:03:13 localhost
dbmail/smtp[10561]: dbmail-message.c,dbmail_message_store: allocating [524288]
bytes of memory for readblock
Jun 29 14:03:13 localhost dbmail/smtp[10561]: pipe.c,store_message_in_blocks:
inserting message:
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '1524']
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_messageblks(is_header, messageblk,blocksize,
physmessage_id)VALUES ('0','\n', '1', '959')]
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [UPDATE dbmail_messages SET unique_id =
'701816680e98e05978e5c6bf568afa51', status = '0' WHERE message_idnr = '1524']
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '1524']
Jun 29 14:03:13 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [UPDATE dbmail_physmessage SET messagesize = '4377', rfcsize = '4418'
WHERE id = '959']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT dbmail_mailboxes.owner_idnr FROM dbmail_mailboxes,
dbmail_messages WHERE dbmail_mailboxes.mailbox_idnr =
dbmail_messages.mailbox_idnr AND dbmail_messages.message_idnr = '1524']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: db.c,db_add_quotum_used: adding
4377 to mailsize
Jun 29 14:03:14 localhost dbmail/smtp[10561]:
db.c.user_idnr_is_delivery_user_idnr: looking up user_idnr for [EMAIL
PROTECTED]@__
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT user_idnr FROM dbmail_users WHERE userid='[EMAIL PROTECTED]@__']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT id FROM dbmail_headername WHERE headername='X-Invalid-Header']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_headervalue (headername_id, physmessage_id,
headervalue) VALUES (80,959,'C/ 629039 312
1T')]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT id FROM dbmail_headername WHERE
headername='X-DBMail-PhysMessage-ID']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_headervalue (headername_id, physmessage_id,
headervalue) VALUES (10,959,'959')]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: pipe.c, insert_messages:
temporary msgidnr is [1524]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: pipe.c, insert_messages: calling
sort_and_deliver for useridnr [3]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT mailbox_idnr FROM dbmail_mailboxes WHERE name='INBOX' AND
owner_idnr='3']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: db.c, db_find_create_mailbox:
mailbox [INBOX] found
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT pm.messagesize FROM dbmail_physmessage pm, dbmail_messages msg
WHERE pm.id = msg.physmessage_id AND message_idnr = '1524']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT 1 FROM dbmail_users WHERE user_idnr = '3' AND (maxmail_size > 0)
AND (curmail_size + '4377' > maxmail_size)]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: misc.c,create_unique_id:
created:6508d47dfded037bf2691eab8caeafad
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [INSERT INTO dbmail_messages (mailbox_idnr,physmessage_id, seen_flag,
answered_flag, deleted_flag, flagged_flag, recent_flag, draft_flag, unique_id,
status) SELECT '1', physmessage_id, seen_flag, answered_flag, deleted_flag,
flagged_flag, recent_flag, draft_flag, '6508d47dfded037bf2691eab8caeafad',
status FROM dbmail_messages WHERE message_idnr = '1524']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: db.c,db_add_quotum_used: adding
4377 to mailsize
Jun 29 14:03:14 localhost dbmail/smtp[10561]:
db.c.user_idnr_is_delivery_user_idnr: no need to look up user_idnr for [EMAIL
PROTECTED]@__
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [UPDATE dbmail_users SET curmail_size = curmail_size + '4377' WHERE
user_idnr= '3']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmail-message.c,
sort_and_deliver: message id=1525, size=4377 is inserted
Jun 29 14:03:14 localhost dbmail/smtp[10561]: pipe.c, insert_messages:
successful sort_and_deliver for useridnr [3]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: insert_messages(): we need to
deliver [0] messages to external addresses
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '1524']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [DELETE FROM dbmail_messages WHERE message_idnr = '1524']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [SELECT message_idnr FROM dbmail_messages WHERE physmessage_id = '959']
Jun 29 14:03:14 localhost dbmail/smtp[10561]: insert_messages(): temporary
message deleted from database
Jun 29 14:03:14 localhost dbmail/smtp[10561]: insert_messages(): End of function
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dbmysql.c,db_query: executing
query [COMMIT]
Jun 29 14:03:14 localhost dbmail/smtp[10561]: main(): freeing dsnuser list
Jun 29 14:03:14 localhost dbmail/smtp[10561]: dsn.c, dsnuser_free: dsnuser freed
Jun 29 14:03:14 localhost dbmail/smtp[10561]: main(): freeing all other lists
Jun 29 14:03:14 localhost dbmail/smtp[10561]: main(): they're all free. we're
done.
Jun 29 14:03:14 localhost dbmail/smtp[10561]: main(): exit code is [0].
