Moved too quickly to get the log in the right place. Trace level on lmtp
is set to 5. It's not going to the local filesystem either, though it
did originally when I tested postfix before setting up dbmail.
Candice
Sep 6 16:55:00 mail1 postfix/smtpd[96731]: connect from
mailfrom.fake.com[deleted]
Sep 6 16:55:00 mail1 postfix/smtpd[96731]: 73E7320AC:
client=mailfrom.fake.com[deleted]
Sep 6 16:55:00 mail1 postfix/cleanup[96733]: 73E7320AC: message-id=<[EMAIL
PROTECTED]>
Sep 6 16:55:00 mail1 postfix/qmgr[96661]: 73E7320AC: from=<[EMAIL PROTECTED]>,
size=689, nrcpt=1 (queue active)
Sep 6 16:55:00 mail1 postfix/smtpd[96731]: disconnect from
mailfrom.fake.com[deleted]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: PerformChildTask(): incoming
connection from [deleted (mail1)]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: PerformChildTask(): client info init
complete, calling client handler
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): incoming buffer: [LHLO
mail1.fake.org]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command issued :cmd [LHLO],
value [mail1.fake.org]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command looked up as
commandtype 0
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): incoming buffer: [MAIL
FROM:<[EMAIL PROTECTED]> SIZE=689]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command issued :cmd [MAIL],
value [FROM:<[EMAIL PROTECTED]> SIZE=689]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command looked up as
commandtype 4
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: misc.c, find_bounded: Found [EMAIL
PROTECTED] of length [27] between '<' and '>' so next skip [33]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): incoming buffer: [RCPT
TO:<[EMAIL PROTECTED]>]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command issued :cmd [RCPT],
value [TO:<[EMAIL PROTECTED]>]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command looked up as
commandtype 9
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: misc.c, find_bounded: Found [EMAIL
PROTECTED] of length [23] between '<' and '>' so next skip [27]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dsn.c, dsnuser_init: dsnuser
initialized
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): incoming buffer: [DATA]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp(): command looked up as
commandtype 3
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT user_idnr FROM dbmail_users WHERE userid='[EMAIL PROTECTED]']
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext:
checking user [EMAIL PROTECTED] in alias table
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext:
checks [-1]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('[EMAIL
PROTECTED]')]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext: into
checking loop
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext:
checking user [EMAIL PROTECTED] to 2
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext:
checking user [2] in alias table
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext:
checks [1]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT deliver_to FROM dbmail_aliases WHERE lower(alias) = lower('2')]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: authsql.c,auth_check_user_ext:
adding [2] to deliver_to address
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dsn.c, dsnuser_resolve_list: user
[EMAIL PROTECTED] found total of [1] aliases
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: main(): requesting sender to begin
message.
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: lmtp.c,lmtp: whole message =
Received: from mailfrom.fake.com (mailfrom.fake.com [69.13.116.1]) by
mail1.fake.org (Postfix) with ESMTP id 73E7320AC for <[EMAIL PROTECTED]>;
Mon, 6 Sep 2004 16:55:00 -0500 (CDT) Received: from mailfrom.fake.com
(localhost.firepipe.net [127.0.0.1]) by mailfrom.fake.com (Postfix) with
ESMTP id 8C11F180D6 for <[EMAIL PROTECTED]>; Mon, 6 Sep 2004 16:46:45
-0500 (EST) From: Candice Quates <[EMAIL PROTECTED]> Reply-To: [EMAIL
PROTECTED] To: [EMAIL PROTECTED] Subject: foobar Date: Mon, 06 Sep 2004
16:46:45 -0500 Sender: [EMAIL PROTECTED] Message-Id: <[EMAIL PROTECTED]>
foobar foobar? foobar
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: header.c,consume_header_line: end of
header found
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: header.c,get_rfc_size: remaining_len
= 23
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: mime_readheader(): entering mime loop
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: mime_readheader(): found double
newline; header size: 14 lines
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT user_idnr FROM dbmail_users WHERE userid='[EMAIL PROTECTED]@__']
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: misc.c,create_unique_id: created:
4b60e6662ca8d17a36236b32afd7e3fa
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT mailbox_idnr FROM dbmail_mailboxes WHERE name='INBOX' AND
owner_idnr='1']
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: db.c, db_find_create_mailbox:
mailbox [INBOX] found
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[INSERT INTO dbmail_physmessage (messagesize, internal_date) VALUES ('0',
CURRENT_TIMESTAMP)]
Sep 6 16:55:00 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[INSERT INTO dbmail_messages(mailbox_idnr, physmessage_id,
unique_id,recent_flag, status) VALUES ('2', '7',
'4b60e6662ca8d17a36236b32afd7e3fa', '1', '5')]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[INSERT INTO dbmail_messageblks(messageblk,blocksize, physmessage_id) VALUES
('Received: from mailfrom.fake.com (mailfrom.fake.com [deleted])\n by
mail1.fake.org (Postfix) with ESMTP id 73E7320AC\n for <[EMAIL PROTECTED]>;
Mon, 6 Sep 2004 16:55:00 -0500 (CDT)\nReceived: from mailfrom.fake.com
(localhost [127.0.0.1])\n by mailfrom.fake.com (Postfix) with ESMTP id
8C11F180D6\n for <[EMAIL PROTECTED]>; Mon, 6 Sep 2004 16:46:45 -0500
(EST)\nFrom: Candice Quates <[EMAIL PROTECTED]>\nReply-To: [EMAIL PROTECTED]:
[EMAIL PROTECTED]: foobar\nDate: Mon, 06 Sep 2004 16:46:45 -0500\nSender:
[EMAIL PROTECTED]: <[EMAIL PROTECTED]>\n\n', '646', '7')]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: store_message_temp(): allocating
[524288] bytes of memory for readblock
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: pipe.c,store_message_in_blocks:
inserting message: foobar foobar? foobar
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[INSERT INTO dbmail_messageblks(messageblk,blocksize, physmessage_id) VALUES
('foobar\nfoobar?\n\nfoobar\n', '23', '7')]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[UPDATE dbmail_messages SET unique_id = '4b60e6662ca8d17a36236b32afd7e3fa',
status = '0' WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[UPDATE dbmail_physmessage SET messagesize = '669', rfcsize = '687' WHERE id =
'7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: 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 = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: db.c,db_add_quotum_used: adding 669
to mailsize
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]:
db.c.user_idnr_is_delivery_user_idnr: looking up user_idnr for [EMAIL
PROTECTED]@__
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT user_idnr FROM dbmail_users WHERE userid='[EMAIL PROTECTED]@__']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: pipe.c, insert_messages: temporary
msgidnr is [7]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: pipe.c, insert_messages: calling
sort_and_deliver for useridnr [2]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): searching value
for config item [SQLREGEX]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): item not found
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): searching value
for config item [LIBSIEVE]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): item not found
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT mailbox_idnr FROM dbmail_mailboxes WHERE name='INBOX' AND
owner_idnr='2']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: db.c, db_find_create_mailbox:
mailbox [INBOX] found
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: 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 = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT 1 FROM dbmail_users WHERE user_idnr = '2' AND (maxmail_size > 0) AND
(curmail_size + '669' > maxmail_size)]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: misc.c,create_unique_id: created:
31c4736a7014ef3bfb6462157efd504f
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: 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, '31c4736a7014ef3bfb6462157efd504f',
status FROM dbmail_messages WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: db.c,db_add_quotum_used: adding 669
to mailsize
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]:
db.c.user_idnr_is_delivery_user_idnr: no need to look up user_idnr for [EMAIL
PROTECTED]@__
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[UPDATE dbmail_users SET curmail_size = curmail_size + '669' WHERE user_idnr =
'2']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: sort.c, sort_and_deliver: message
id=0, size=669 is inserted
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: pipe.c, insert_messages: successful
sort_and_deliver for useridnr [2]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): searching value
for config item [AUTO_NOTIFY]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): found value [no]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): searching value
for config item [AUTO_REPLY]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: GetConfigValue(): found value [no]
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: insert_messages(): we need to
deliver [0] messages to external addresses
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT physmessage_id FROM dbmail_messages WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[DELETE FROM dbmail_messages WHERE message_idnr = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[SELECT message_idnr FROM dbmail_messages WHERE physmessage_id = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[DELETE FROM dbmail_physmessage WHERE id = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: dbmysql.c,db_query: executing query
[DELETE FROM dbmail_messageblks WHERE physmessage_id = '7']
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: insert_messages(): temporary message
deleted from database
Sep 6 16:55:01 mail1 dbmail/lmtpd[96635]: insert_messages(): End of function
Sep 6 16:55:01 mail1 postfix/lmtp[96736]: 73E7320AC: to=<[EMAIL PROTECTED]>,
relay=mail1.fake.org[66.55.38.237], delay=1, status=sent (215 Recipient <[EMAIL
PROTECTED]> OK)
