20160728 Bugfix (introduced: 20090614): with concurrent connections from the same client IP address, and after-220 tests enabled, postscreen could overwrite the cached "all tests completed" result of one connection that completed the after-220 tests, with the "some tests not completed" result of a concurrent connection where the client hung up before completing the after-220 tests. Files: postscreen_misc.c, postscreen_state.c, postscreen.h, postscreen_tests.c, postscreen.c, postscreen_smtpd.c, postscreen_early.c. diff --exclude=man --exclude=html --exclude=README_FILES --exclude=INSTALL --exclude=.indent.pro --exclude=Makefile.in -r -ur /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen.c ./src/postscreen/postscreen.c --- /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen.c 2016-04-11 18:16:53.000000000 -0400 +++ ./src/postscreen/postscreen.c 2016-07-30 08:52:11.000000000 -0400 @@ -766,6 +766,7 @@ * valid. */ if ((state->flags & PSC_STATE_MASK_ANY_FAIL) == 0 + && state->client_info->concurrency == 1 && psc_cache_map != 0 && (stamp_str = psc_cache_lookup(psc_cache_map, state->smtp_client_addr)) != 0) { saved_flags = state->flags; @@ -779,6 +780,13 @@ psc_conclude(state); return; } + } else if (state->client_info->concurrency > 1) { + saved_flags = state->flags; + psc_todo_tests(state, event_time()); + state->flags |= saved_flags; + if (msg_verbose) + msg_info("%s: new + recent flags: %s", + myname, psc_print_state_flags(state->flags, myname)); } else { saved_flags = state->flags; psc_new_tests(state); @@ -830,6 +838,7 @@ void *unused_context) { PSC_STATE dummy; + PSC_CLIENT_INFO dummy_client_info; /* * This function is called by the cache cleanup pseudo thread. @@ -839,6 +848,7 @@ * silly logging we remove the cache entry only after all tests have * expired longer ago than the cache retention time. */ + dummy.client_info = &dummy_client_info; psc_parse_tests(&dummy, stamp_str, event_time() - var_psc_cache_ret); return ((dummy.flags & PSC_STATE_MASK_ANY_TODO) == 0); } diff --exclude=man --exclude=html --exclude=README_FILES --exclude=INSTALL --exclude=.indent.pro --exclude=Makefile.in -r -ur /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen.h ./src/postscreen/postscreen.h --- /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen.h 2016-01-23 19:39:28.000000000 -0500 +++ ./src/postscreen/postscreen.h 2016-07-28 18:22:56.000000000 -0400 @@ -55,6 +55,15 @@ #define PSC_TINDX_BYTNAME(tname) (PSC_TINDX_ ## tname) /* + * Per-client shared state. + */ +typedef struct { + int concurrency; /* per-client */ + int pass_new_count; /* per-client */ + time_t expire_time[PSC_TINDX_COUNT]; /* per-test expiration */ +} PSC_CLIENT_INFO; + + /* * Per-session state. */ typedef struct { @@ -66,13 +75,12 @@ char *smtp_client_port; /* client port */ char *smtp_server_addr; /* server address */ char *smtp_server_port; /* server port */ - int client_concurrency; /* per-client */ const char *final_reply; /* cause for hanging up */ VSTRING *send_buf; /* pending output */ /* Test context. */ struct timeval start_time; /* start of current test */ const char *test_name; /* name of current test */ - time_t expire_time[PSC_TINDX_COUNT]; /* per-test expiration */ + PSC_CLIENT_INFO *client_info; /* shared client state */ VSTRING *dnsbl_reply; /* dnsbl reject text */ int dnsbl_score; /* saved DNSBL score */ int dnsbl_ttl; /* saved DNSBL TTL */ @@ -95,11 +103,14 @@ * Emulate legacy ad-hoc variables on top of indexable time stamps. This * avoids massive scar tissue during initial feature development. */ -#define pregr_stamp expire_time[PSC_TINDX_PREGR] -#define dnsbl_stamp expire_time[PSC_TINDX_DNSBL] -#define pipel_stamp expire_time[PSC_TINDX_PIPEL] -#define nsmtp_stamp expire_time[PSC_TINDX_NSMTP] -#define barlf_stamp expire_time[PSC_TINDX_BARLF] +#define pregr_stamp client_info->expire_time[PSC_TINDX_PREGR] +#define dnsbl_stamp client_info->expire_time[PSC_TINDX_DNSBL] +#define pipel_stamp client_info->expire_time[PSC_TINDX_PIPEL] +#define nsmtp_stamp client_info->expire_time[PSC_TINDX_NSMTP] +#define barlf_stamp client_info->expire_time[PSC_TINDX_BARLF] + + /* Minize the patch size for stable releases. */ +#define client_concurrency client_info->concurrency /* * Special expiration time values. @@ -489,17 +500,21 @@ #define PSC_INIT_TESTS(dst) do { \ time_t *_it_stamp_p; \ (dst)->flags = 0; \ - for (_it_stamp_p = (dst)->expire_time; \ - _it_stamp_p < (dst)->expire_time + PSC_TINDX_COUNT; \ + for (_it_stamp_p = (dst)->client_info->expire_time; \ + _it_stamp_p < (dst)->client_info->expire_time + PSC_TINDX_COUNT; \ _it_stamp_p++) \ *_it_stamp_p = PSC_TIME_STAMP_INVALID; \ } while (0) +#define PSC_INIT_TEST_FLAGS_ONLY(dst) do { \ + (dst)->flags = 0; \ + } while (0) #define PSC_BEGIN_TESTS(state, name) do { \ (state)->test_name = (name); \ GETTIMEOFDAY(&(state)->start_time); \ } while (0) extern void psc_new_tests(PSC_STATE *); extern void psc_parse_tests(PSC_STATE *, const char *, time_t); +extern void psc_todo_tests(PSC_STATE *, time_t); extern char *psc_print_tests(VSTRING *, PSC_STATE *); extern char *psc_print_grey_key(VSTRING *, const char *, const char *, const char *, const char *); diff --exclude=man --exclude=html --exclude=README_FILES --exclude=INSTALL --exclude=.indent.pro --exclude=Makefile.in -r -ur /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_early.c ./src/postscreen/postscreen_early.c --- /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_early.c 2016-01-23 19:38:38.000000000 -0500 +++ ./src/postscreen/postscreen_early.c 2016-07-26 19:26:10.000000000 -0400 @@ -92,8 +92,8 @@ state->flags |= PSC_STATE_FLAG_BYTINDX_PASS(tindx); } /* Update expiration even if the test was completed or disabled. */ - if (state->expire_time[tindx] < now + state->dnsbl_ttl) - state->expire_time[tindx] = now + state->dnsbl_ttl; + if (state->client_info->expire_time[tindx] < now + state->dnsbl_ttl) + state->client_info->expire_time[tindx] = now + state->dnsbl_ttl; } } } diff --exclude=man --exclude=html --exclude=README_FILES --exclude=INSTALL --exclude=.indent.pro --exclude=Makefile.in -r -ur /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_misc.c ./src/postscreen/postscreen_misc.c --- /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_misc.c 2011-01-02 11:20:40.000000000 -0500 +++ ./src/postscreen/postscreen_misc.c 2016-07-30 09:20:45.000000000 -0400 @@ -105,13 +105,17 @@ if ((state->flags & PSC_STATE_MASK_ANY_PASS) != 0 && (state->flags & PSC_STATE_MASK_ANY_PASS) == PSC_STATE_FLAGS_TODO_TO_PASS(state->flags & PSC_STATE_MASK_ANY_TODO)) - msg_info("PASS %s [%s]:%s", (state->flags & PSC_STATE_FLAG_NEW) == 0 ? + msg_info("PASS %s [%s]:%s", (state->flags & PSC_STATE_FLAG_NEW) == 0 + || state->client_info->pass_new_count++ > 0 ? "OLD" : "NEW", PSC_CLIENT_ADDR_PORT(state)); /* * Update the postscreen cache. This still supports a scenario where a * client gets whitelisted in the course of multiple sessions, as long as - * that client does not "fail" any test. + * that client does not "fail" any test. Don't try to optimize away cache + * updates; we want cached information to be up-to-date even if a test + * result is renewed during overlapping SMTP sessions, and even if + * 'postfix reload' happens in the middle of that. */ if ((state->flags & PSC_STATE_MASK_ANY_UPDATE) != 0 && psc_cache_map != 0) { diff --exclude=man --exclude=html --exclude=README_FILES --exclude=INSTALL --exclude=.indent.pro --exclude=Makefile.in -r -ur /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_state.c ./src/postscreen/postscreen_state.c --- /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_state.c 2014-12-06 20:35:33.000000000 -0500 +++ ./src/postscreen/postscreen_state.c 2016-07-28 18:24:32.000000000 -0400 @@ -61,7 +61,8 @@ /* psc_new_session_state() creates a new session state object /* for the specified client stream, and increments the /* psc_check_queue_length counter. The flags and per-test time -/* stamps are initialized with PSC_INIT_TESTS(). The addr and +/* stamps are initialized with PSC_INIT_TESTS(), or for concurrent +/* sessions, with PSC_INIT_TEST_FLAGS_ONLY(). The addr and /* port arguments are null-terminated strings with the remote /* SMTP client endpoint. The _reply members are set to /* polite "try again" SMTP replies. The protocol member is set @@ -149,10 +150,8 @@ const char *server_port) { PSC_STATE *state; - HTABLE_INFO *ht; state = (PSC_STATE *) mymalloc(sizeof(*state)); - PSC_INIT_TESTS(state); if ((state->smtp_client_stream = stream) != 0) psc_check_queue_length++; state->smtp_server_fd = (-1); @@ -188,10 +187,19 @@ /* * Update the per-client session count. */ - if ((ht = htable_locate(psc_client_concurrency, client_addr)) == 0) - ht = htable_enter(psc_client_concurrency, client_addr, (void *) 0); - ht->value += 1; - state->client_concurrency = CAST_ANY_PTR_TO_INT(ht->value); + if ((state->client_info = (PSC_CLIENT_INFO *) + htable_find(psc_client_concurrency, client_addr)) == 0) { + state->client_info = (PSC_CLIENT_INFO *) + mymalloc(sizeof(state->client_info[0])); + (void) htable_enter(psc_client_concurrency, client_addr, + (void *) state->client_info); + PSC_INIT_TESTS(state); + state->client_info->concurrency = 1; + state->client_info->pass_new_count = 0; + } else { + PSC_INIT_TEST_FLAGS_ONLY(state); + state->client_info->concurrency += 1; + } return (state); } @@ -210,9 +218,8 @@ state->smtp_client_addr)) == 0) msg_panic("%s: unknown client address: %s", myname, state->smtp_client_addr); - if (--(ht->value) == 0) - htable_delete(psc_client_concurrency, state->smtp_client_addr, - (void (*) (void *)) 0); + if (--(state->client_info->concurrency) == 0) + htable_delete(psc_client_concurrency, state->smtp_client_addr, myfree); if (state->smtp_client_stream != 0) { event_server_disconnect(state->smtp_client_stream); diff --exclude=man --exclude=html --exclude=README_FILES --exclude=INSTALL --exclude=.indent.pro --exclude=Makefile.in -r -ur /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_tests.c ./src/postscreen/postscreen_tests.c --- /var/tmp/postfix-3.2-20160625/src/postscreen/postscreen_tests.c 2013-05-12 13:09:08.000000000 -0400 +++ ./src/postscreen/postscreen_tests.c 2016-07-28 18:20:17.000000000 -0400 @@ -17,6 +17,11 @@ /* const char *stamp_text; /* time_t time_value; /* +/* void psc_todo_tests(state, time_value) +/* PSC_STATE *state; +/* const char *stamp_text; +/* time_t time_value; +/* /* char *psc_print_tests(buffer, state) /* VSTRING *buffer; /* PSC_STATE *state; @@ -41,13 +46,18 @@ /* zeroes all the flags bits. These values are not meant to /* be stored into the postscreen(8) cache. /* +/* PSC_INIT_TEST_FLAGS_ONLY() zeroes all the flag bits. It +/* should be used when the time stamps are already initialized. +/* /* psc_new_tests() sets all test expiration time stamps to -/* PSC_TIME_STAMP_NEW, and overwrites all flags bits. Only -/* enabled tests are flagged with PSC_STATE_FLAG_TODO; the -/* object is flagged with PSC_STATE_FLAG_NEW. +/* PSC_TIME_STAMP_NEW, and invokes psc_todo_tests(). +/* +/* psc_parse_tests() parses a cache file record and invokes +/* psc_todo_tests(). /* -/* psc_parse_tests() parses a cache file record and overwrites -/* all flags bits. Tests are considered "expired" when they +/* psc_todo_tests() overwrites all per-session flag bits, and +/* populates the flags based on test expiration time stamp +/* information. Tests are considered "expired" when they /* would be expired at the specified time value. Only enabled /* tests are flagged as "expired"; the object is flagged as /* "new" if some enabled tests have "new" time stamps. @@ -125,11 +135,6 @@ { /* - * We know this client is brand new. - */ - state->flags = PSC_STATE_FLAG_NEW; - - /* * Give all tests a PSC_TIME_STAMP_NEW time stamp, so that we can later * recognize cache entries that haven't passed all enabled tests. When we * write a cache entry to the database, any new-but-disabled tests will @@ -142,19 +147,9 @@ state->barlf_stamp = PSC_TIME_STAMP_NEW; /* - * Don't flag disabled tests as "todo", because there would be no way to - * make those bits go away. + * Determine what tests need to be completed. */ - if (PSC_PREGR_TEST_ENABLE()) - state->flags |= PSC_STATE_FLAG_PREGR_TODO; - if (PSC_DNSBL_TEST_ENABLE()) - state->flags |= PSC_STATE_FLAG_DNSBL_TODO; - if (var_psc_pipel_enable) - state->flags |= PSC_STATE_FLAG_PIPEL_TODO; - if (var_psc_nsmtp_enable) - state->flags |= PSC_STATE_FLAG_NSMTP_TODO; - if (var_psc_barlf_enable) - state->flags |= PSC_STATE_FLAG_BARLF_TODO; + psc_todo_tests(state, PSC_TIME_STAMP_NEW + 1); } /* psc_parse_tests - parse test results from cache */ @@ -165,29 +160,18 @@ { const char *start = stamp_str; char *cp; - time_t *time_stamps = state->expire_time; + time_t *time_stamps = state->client_info->expire_time; time_t *sp; /* - * We don't know what tests have expired or have never passed. - */ - state->flags = 0; - - /* * Parse the cache entry, and allow for older postscreen versions that * implemented fewer tests. We pretend that the newer tests were disabled * at the time that the cache entry was written. - * - * Flag the cache entry as "new" when the cache entry has fields for all - * enabled tests, but the remote SMTP client has not yet passed all those - * tests. */ for (sp = time_stamps; sp < time_stamps + PSC_TINDX_COUNT; sp++) { *sp = strtoul(start, &cp, 10); if (*start == 0 || (*cp != '\0' && *cp != ';') || errno == ERANGE) *sp = PSC_TIME_STAMP_DISABLED; - if (*sp == PSC_TIME_STAMP_NEW) - state->flags |= PSC_STATE_FLAG_NEW; if (msg_verbose) msg_info("%s -> %lu", start, (unsigned long) *sp); if (*cp == ';') @@ -197,6 +181,34 @@ } /* + * Determine what tests need to be completed. + */ + psc_todo_tests(state, time_value); +} + +/* psc_todo_tests - determine what tests to perform */ + +void psc_todo_tests(PSC_STATE *state, time_t time_value) +{ + time_t *time_stamps = state->client_info->expire_time; + time_t *sp; + + /* + * Reset all per-session flags. + */ + state->flags = 0; + + /* + * Flag the tests as "new" when the cache entry has fields for all + * enabled tests, but the remote SMTP client has not yet passed all those + * tests. + */ + for (sp = time_stamps; sp < time_stamps + PSC_TINDX_COUNT; sp++) { + if (*sp == PSC_TIME_STAMP_NEW) + state->flags |= PSC_STATE_FLAG_NEW; + } + + /* * Don't flag disabled tests as "todo", because there would be no way to * make those bits go away. */