Amavisd uses different mail_id than the one i requested while releasing quarantined mail

[Zhang Huangbin]

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/