Dear developers & users,
I found a strange issue on my server after upgraded PostgreSQL 8.4 to 9.1 and
Amavisd 2.8 to 2.9.1, any help is appreciated.
I tried to release quarantined email with my own web admin panel through
$policy_bank{'AM.PDP-INET'}, i submitted correct values of mail_id and
secret_id in request, but Amavisd used a different mail_id to fetch records in
sql database.
It worked well before upgrading PostgreSQL and Amavisd.
The request command i used to release quarantined email:
request=release
mail_id=LaZYliMnsoDs
secret_id=TERCp2Bi5_yr
quar_type=Q
Before i released it, i checked with SQL command line to confirm i have correct
SQL records in tables "msgs" and "quarantine", then i release quarantined mail
with my own web admin panel and check Amavisd log file, and the strange thing
is Amavisd used a different (and non-exist) mail_id to fetch sql records.
Below is detailed log. As you can see, i submitted "mail_id= LaZYliMnsoDs" and
"secret_id=TERCp2Bi5_yr", but Amavisd uses "mail_id=5pnbv-lk-5wX".
Any way i can fix it?
Aug 17 22:11:54 mail postfix/qmgr[5552]: 4942516B4D: removed
Aug 17 22:16:02 mail amavis[26458]: (26458-11) Net::Server: 2014/08/17-22:16:02
CONNECT TCP Peer: "127.0.0.1:42701" Local: "127.0.0.1:9998"
Aug 17 22:16:02 mail amavis[26458]: idle_proc, hi : was idle, 558394.1 ms,
total idle 239383.103 s, busy 9.994 s
Aug 17 22:16:02 mail amavis[26458]: loaded base policy bank
Aug 17 22:16:02 mail amavis[26458]: loaded policy bank "AM.PDP-INET"
Aug 17 22:16:02 mail amavis[26458]: lookup_ip_acl (inet_acl) arr.obj:
key="127.0.0.1" matches "127.0.0.1", result=1
Aug 17 22:16:02 mail amavis[26458]: process_request: fileno sock=10, STDIN=0,
STDOUT=1
Aug 17 22:16:02 mail amavis[26458]: get_deadline switch_to_my_time(new request)
- deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: prolong_timer switch_to_my_time(new
request): timer 336, was 0, deadline in 480.0 s
Aug 17 22:16:02 mail amavis[26458]: process_request:
suggested_protocol="AM.PDP" on a TCP socket
Aug 17 22:16:02 mail amavis[26458]: process_policy_request: 0,
/usr/sbin/amavisd, fileno=10
Aug 17 22:16:02 mail amavis[26458]: switch_to_client_time 480 s, start
receiving AM.PDP data
Aug 17 22:16:02 mail amavis[26458]: get_deadline switch_to_my_time(rx AM.PDP
line) - deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: prolong_timer switch_to_my_time(rx AM.PDP
line): timer 336, was 480, deadline in 480.0 s
Aug 17 22:16:02 mail amavis[26458]: policy protocol: request=release
Aug 17 22:16:02 mail amavis[26458]: switch_to_client_time 480 s, receiving
AM.PDP data
Aug 17 22:16:02 mail amavis[26458]: get_deadline switch_to_my_time(rx AM.PDP
line) - deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: prolong_timer switch_to_my_time(rx AM.PDP
line): timer 336, was 480, deadline in 480.0 s
Aug 17 22:16:02 mail amavis[26458]: policy protocol: mail_id=LaZYliMnsoDs
Aug 17 22:16:02 mail amavis[26458]: switch_to_client_time 480 s, receiving
AM.PDP data
Aug 17 22:16:02 mail amavis[26458]: get_deadline switch_to_my_time(rx AM.PDP
line) - deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: prolong_timer switch_to_my_time(rx AM.PDP
line): timer 336, was 480, deadline in 480.0 s
Aug 17 22:16:02 mail amavis[26458]: policy protocol: secret_id=TERCp2Bi5_yr
Aug 17 22:16:02 mail amavis[26458]: switch_to_client_time 480 s, receiving
AM.PDP data
Aug 17 22:16:02 mail amavis[26458]: get_deadline switch_to_my_time(rx AM.PDP
line) - deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: prolong_timer switch_to_my_time(rx AM.PDP
line): timer 336, was 480, deadline in 480.0 s
Aug 17 22:16:02 mail amavis[26458]: policy protocol: quar_type=Q
Aug 17 22:16:02 mail amavis[26458]: switch_to_client_time 480 s, receiving
AM.PDP data
Aug 17 22:16:02 mail amavis[26458]: get_deadline switch_to_my_time(rx entire
AM.PDP request) - deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: prolong_timer switch_to_my_time(rx entire
AM.PDP request): timer 336, was 480, deadline in 480.0 s
Aug 17 22:16:02 mail amavis[26458]: TempDir::prepare_dir: created directory
/var/spool/amavisd/tmp/amavis-20140817T221602-26458-gmAQNvPq
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) preprocess_policy_query:
opening in sql: 5pnbv-lk-5wX
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) preprocess_policy_query:
missing partition_tag in request, fetching msgs record for mail_id=5pnbv-lk-5wX
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) sql begin, nontransaction
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) sql: preparing and
executing (1 args): SELECT partition_tag FROM msgs WHERE mail_id=?
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) release: no records with
msgs.mail_id=5pnbv-lk-5wX in a database, trying to read from a quar. anyway
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) release: opening
mail_id=5pnbv-lk-5wX, partition_tag=
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) sql begin, nontransaction
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) sql: preparing and
executing (2 args): SELECT mail_text FROM quarantine WHERE partition_tag=? AND
mail_id=? ORDER BY chunk_ind
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) Amavis::IO::SQL::open r
drv=Pg (SELECT mail_text FROM quarantine WHERE partition_tag=? AND mail_id=?
ORDER BY chunk_ind); key=5pnbv-lk-5wX, p_tag=, s:
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) Amavis::IO::SQL::open
key=5pnbv-lk-5wX, p_tag=: no such record
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) TempDir::DESTROY called
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) TempDir removal: empty
tempdir is being removed:
/var/spool/amavisd/tmp/amavis-20140817T221602-26458-gmAQNvPq
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) rmdir_recursively:
/var/spool/amavisd/tmp/amavis-20140817T221602-26458-gmAQNvPq, excl=
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) (!!)policy_server
FAILED: Can't open sql obj for reading: No such file or directory at (eval 109)
line 375, <GEN248> line 5.
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) size: 0, TIMING [total 5
ms] - got data: 0.0 (0%)0, mkdir tempdir: 0.9 (18%)18, rmdir: 3.7 (75%)94,
rundown: 0.3 (6%)100
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) switch_to_client_time
480 s, receiving AM.PDP data
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) get_deadline
switch_to_my_time(end of AM.PDP session) - deadline in 480.0 s, set to 336.000 s
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) prolong_timer
switch_to_my_time(end of AM.PDP session): timer 336, was 480, deadline in 480.0
s
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) exiting process_request
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) idle_proc, bye: was
busy, 10.0 ms, total idle 239383.103 s, busy 10.004 s
Aug 17 22:16:02 mail amavis[26458]: (rel-5pnbv-lk-5wX) load: 0 %, total idle
239383.103 s, busy 10.004 s
----
Zhang Huangbin
iRedMail: free, open source mail server solution for Red Hat,
CentOS, Debian, Ubuntu, FreeBSD, OpenBSD:
http://www.iredmail.org/
