def __sendmail(conn, user, client_address, throttle_tracking_id, throttle_name, throttle_value, throttle_kind, throttle_info, throttle_value_unit=None): """Construct and send notification email.""" # conn: SQL connection cursor # user: user email address # client_address: client IP address # throttle_tracking_id: value of sql column `throttle_tracking.id` # throttle_name: name of throttle settings: msg_size, max_quota, max_msgs # throttle_value: value throttle setting # throttle_kind: one of throttle kinds: inbound, outbound # throttle_info: detailed throttle setting # throttle_value_unit: unit of throttle setting. e.g 'bytes' for max_quota # and msg_size. if not throttle_value_unit: throttle_value_unit = '' try: _subject = 'Throttle quota exceeded: %s, %s=%d %s' % ( user, throttle_name, throttle_value, throttle_value_unit) _body = '- User: '******'\n' _body += '- Client IP address: ' + client_address + '\n' _body += '- Throttle type: ' + throttle_kind + '\n' _body += '- Throttle setting: ' + throttle_name + '\n' _body += '- Limit: %d %s\n' % (throttle_value, throttle_value_unit) _body += '- Detailed setting: ' + throttle_info + '\n' utils.sendmail(subject=_subject, mail_body=_body) logger.info( 'Sent notification email to admin(s) to report quota exceed: user=%s, %s=%d.' % (user, throttle_name, throttle_value)) if throttle_tracking_id: _now = int(time.time()) # Update last_notify_time. _sql = """UPDATE throttle_tracking SET last_notify_time=%d WHERE id=%d; """ % (_now, throttle_tracking_id) try: conn.execute(_sql) logger.debug('Updated last notify time.') except Exception as e: logger.error( 'Error while updating last notify time of quota exceed: %s.' % (repr(e))) return (True, ) except Exception as e: logger.error('Error while sending notification email: %s' % repr(e)) return (False, repr(e))
def apply_throttle(conn, conn_vmail, user, client_address, protocol_state, size, recipient_count, instance_id, is_sender_throttling=True, is_external_sender=False): possible_addrs = [client_address, '@ip'] if user: possible_addrs += utils.get_policy_addresses_from_email(mail=user) (_username, _domain) = user.split('@', 1) alias_target_sender_domain = get_alias_target_domain( alias_domain=_domain, conn=conn_vmail) if alias_target_sender_domain: _mail = _username + '@' + alias_target_sender_domain possible_addrs += utils.get_policy_addresses_from_email(mail=_mail) sql_user = sqlquote(user) if utils.is_ipv4(client_address): possible_addrs += utils.wildcard_ipv4(client_address) if is_sender_throttling: throttle_type = 'sender' throttle_kind = 'outbound' if is_external_sender: throttle_kind = 'external' else: throttle_type = 'recipient' throttle_kind = 'inbound' sql = """ SELECT id, account, priority, period, max_msgs, max_quota, msg_size FROM throttle WHERE kind=%s AND account IN %s ORDER BY priority DESC """ % (sqlquote(throttle_kind), sqlquote(possible_addrs)) logger.debug('[SQL] Query throttle setting: {}'.format(sql)) qr = conn.execute(sql) throttle_records = qr.fetchall() logger.debug('[SQL] Query result: {}'.format(throttle_records)) if not throttle_records: logger.debug('No {} throttle setting.'.format(throttle_type)) return SMTP_ACTIONS['default'] # Time of now. used for init_time and last_time. now = int(time.time()) # construct the throttle setting t_settings = {} t_setting_ids = {} t_setting_keys = {} # Inherit throttle settings with lower priority. continue_check_msg_size = True continue_check_max_msgs = True continue_check_max_quota = True # print detailed throttle setting throttle_info = '' # sql where statements used to track throttle. # (tid = tid AND account = `user`) tracking_sql_where = set() for rcd in throttle_records: (_id, _account, _priority, _period, _max_msgs, _max_quota, _msg_size) = rcd # Skip throttle setting which doesn't have period if not _period: continue t_setting_keys[(_id, _account)] = [] t_setting_ids[_id] = _account tracking_sql_where.add('(tid=%d AND account=%s)' % (_id, sqlquote(client_address))) if continue_check_msg_size and _msg_size >= 0: continue_check_msg_size = False t_settings['msg_size'] = { 'value': _msg_size, 'period': _period, 'tid': _id, 'account': _account, 'tracking_id': None, 'track_key': [], 'expired': False, 'cur_msgs': 0, 'cur_quota': 0, 'init_time': 0 } t_setting_keys[(_id, _account)].append('msg_size') tracking_sql_where.add('(tid=%d AND account=%s)' % (_id, sql_user)) throttle_info += 'msg_size=%(value)d (bytes)/id=%(tid)d/account=%(account)s; ' % t_settings[ 'msg_size'] if continue_check_max_msgs and _max_msgs >= 0: continue_check_max_msgs = False t_settings['max_msgs'] = { 'value': _max_msgs, 'period': _period, 'tid': _id, 'account': _account, 'tracking_id': None, 'track_key': [], 'expired': False, 'cur_msgs': 0, 'cur_quota': 0, 'init_time': 0 } t_setting_keys[(_id, _account)].append('max_msgs') tracking_sql_where.add('(tid=%d AND account=%s)' % (_id, sql_user)) throttle_info += 'max_msgs=%(value)d/id=%(tid)d/account=%(account)s; ' % t_settings[ 'max_msgs'] if continue_check_max_quota and _max_quota >= 0: continue_check_max_quota = False t_settings['max_quota'] = { 'value': _max_quota, 'period': _period, 'tid': _id, 'account': _account, 'tracking_id': None, 'track_key': [], 'expired': False, 'cur_msgs': 0, 'cur_quota': 0, 'init_time': 0 } t_setting_keys[(_id, _account)].append('max_quota') tracking_sql_where.add('(tid=%d AND account=%s)' % (_id, sql_user)) throttle_info += 'max_quota=%(value)d (bytes)/id=%(tid)d/account=%(account)s; ' % t_settings[ 'max_quota'] if not t_settings: logger.debug('No valid {} throttle setting.'.format(throttle_type)) return SMTP_ACTIONS['default'] else: logger.debug('{} throttle setting: {}'.format(throttle_type, throttle_info)) # Update track_key. for (_, v) in list(t_settings.items()): t_account = v['account'] addr_type = utils.is_valid_amavisd_address(t_account) if addr_type in ['ip', 'catchall_ip']: # Track based on IP address v['track_key'].append(client_address) elif addr_type in ['wildcard_ip', 'wildcard_addr']: # Track based on wildcard IP or sender address v['track_key'].append(t_account) else: # Track based on sender email address v['track_key'].append(user) # Get throttle tracking data. # Construct SQL query WHERE statement sql = """SELECT id, tid, account, cur_msgs, cur_quota, init_time, last_time, last_notify_time FROM throttle_tracking WHERE %s """ % ' OR '.join(tracking_sql_where) logger.debug('[SQL] Query throttle tracking data: {}'.format(sql)) qr = conn.execute(sql) tracking_records = qr.fetchall() logger.debug('[SQL] Query result: {}'.format(tracking_records)) # `throttle.id`. syntax: {(tid, account): id} tracking_ids = {} for rcd in tracking_records: (_id, _tid, _account, _cur_msgs, _cur_quota, _init_time, _last_time, _last_notify_time) = rcd tracking_ids[(_tid, _account)] = _id if not _init_time: _init_time = now # Get special throttle setting name: msg_size, max_msgs, max_quota t_setting_account = t_setting_ids[_tid] for t_name in t_setting_keys.get((_tid, t_setting_account)): if t_name in t_settings: t_settings[t_name]['tracking_id'] = _id t_settings[t_name]['cur_msgs'] = _cur_msgs t_settings[t_name]['cur_quota'] = _cur_quota t_settings[t_name]['init_time'] = _init_time t_settings[t_name]['last_time'] = _last_time t_settings[t_name]['last_notify_time'] = _last_notify_time logger.debug('Tracking IDs: {}'.format(tracking_ids)) if 'msg_size' in t_settings: ts = t_settings['msg_size'] msg_size = ts['value'] _tracking_id = ts['tracking_id'] _period = int(ts.get('period', 0)) _init_time = int(ts.get('init_time', 0)) _last_time = int(ts.get('last_time', 0)) _last_notify_time = int(ts.get('last_notify_time', 0)) # Check message size if size > msg_size > 0: logger.info('[{}] [{}] Quota exceeded: {} throttle for ' 'msg_size, current: {} bytes. ' '({})'.format(client_address, user, throttle_type, size, throttle_info)) if (not _last_notify_time) or ( not (_init_time < _last_notify_time <= (_init_time + _period))): __sendmail(conn=conn, user=user, client_address=client_address, throttle_tracking_id=_tracking_id, throttle_name='msg_size', throttle_value=msg_size, throttle_kind=throttle_kind, throttle_info=throttle_info, throttle_value_unit='bytes') # Construct and send notification email try: _subject = 'Throttle quota exceeded: %s, mssage_size=%d bytes' % ( user, size) _body = '- User: '******'\n' _body += '- Throttle type: ' + throttle_kind + '\n' _body += '- Client IP address: ' + client_address + '\n' _body += '- Limit of single message size: %d bytes\n' % msg_size _body += '- Throttle setting(s): ' + throttle_info + '\n' utils.sendmail(subject=_subject, mail_body=_body) except Exception as e: logger.error( 'Error while sending notification email: {}'.format(e)) return SMTP_ACTIONS['reject_quota_exceeded'] else: # Show the time tracking record is about to expire _left_seconds = _init_time + _period - _last_time logger.info('[{}] {} throttle, {} -> msg_size ' '({}/{}, period: {} seconds, ' '{})'.format(client_address, throttle_type, user, size, msg_size, _period, utils.pretty_left_seconds(_left_seconds))) if 'max_msgs' in t_settings: ts = t_settings['max_msgs'] max_msgs = ts['value'] _cur_msgs = ts['cur_msgs'] _tracking_id = ts['tracking_id'] _period = int(ts.get('period', 0)) _init_time = int(ts.get('init_time', 0)) _last_time = int(ts.get('last_time', 0)) _last_notify_time = int(ts.get('last_notify_time', 0)) if _period and now > (_init_time + _period): logger.debug('Existing max_msg tracking expired, reset.') ts['expired'] = True _init_time = now _last_time = now _cur_msgs = 0 _requested_max_msgs = _cur_msgs + recipient_count if _requested_max_msgs >= max_msgs > 0: logger.info('[{}] [{}] Quota exceeded: {} throttle for ' 'max_msgs, recipient_count={}, {}->{}/{}. ' '({})'.format(client_address, user, throttle_type, recipient_count, _cur_msgs, _requested_max_msgs, max_msgs, throttle_info)) # Send notification email if matches any of: # 1: first exceed # 2: last notify time is not between _init_time and (_init_time + _period) if (not _last_notify_time) or ( not (_init_time < _last_notify_time <= (_init_time + _period))): __sendmail(conn=conn, user=user, client_address=client_address, throttle_tracking_id=_tracking_id, throttle_name='max_msgs', throttle_value=max_msgs, throttle_kind=throttle_kind, throttle_info=throttle_info) return SMTP_ACTIONS['reject_quota_exceeded'] else: # Show the time tracking record is about to expire _left_seconds = _init_time + _period - _last_time logger.info('[{}] {} throttle, {} -> max_msgs ' '({}->{}/{}, period: {} seconds, ' '{})'.format(client_address, throttle_type, user, _cur_msgs, _requested_max_msgs, max_msgs, _period, utils.pretty_left_seconds(_left_seconds))) if 'max_quota' in t_settings: ts = t_settings['max_quota'] max_quota = ts['value'] _cur_quota = ts.get('cur_quota', 0) _tracking_id = ts['tracking_id'] _period = int(ts.get('period', 0)) _init_time = int(ts.get('init_time', 0)) _last_time = int(ts.get('last_time', 0)) if _period and now > (_init_time + _period): # tracking record expired logger.info('Period of max_quota expired, reset.') ts['expired'] = True _init_time = now _last_time = now _cur_quota = 0 if _cur_quota > max_quota > 0: logger.info('[{}] [{}] Quota exceeded: {} throttle for ' 'max_quota, current: {}. ({})'.format( client_address, user, throttle_type, _cur_quota, throttle_info)) if (not _last_notify_time) or ( not (_init_time < _last_notify_time <= (_init_time + _period))): __sendmail(conn=conn, user=user, client_address=client_address, throttle_tracking_id=_tracking_id, throttle_name='max_quota', throttle_value=max_quota, throttle_kind=throttle_kind, throttle_info=throttle_info, throttle_value_unit='bytes') return SMTP_ACTIONS['reject_quota_exceeded'] else: # Show the time tracking record is about to expire _left_seconds = _init_time + _period - _last_time logger.info('[{}] {} throttle, {} -> max_quota ' '({}/{}, period: {} seconds, ' '{})'.format(client_address, throttle_type, user, _cur_quota, max_quota, _period, utils.pretty_left_seconds(_left_seconds))) # Update tracking record. # # SQL statements used to update tracking data if not rejected: # init_time, cur_msgs, cur_quota, last_time sql_inserts = [] # {tracking_id: ['last_time=xxx', 'init_time=xxx', ...]} sql_updates = {} for (_, v) in list(t_settings.items()): tid = v['tid'] for k in v['track_key']: if (tid, k) in tracking_ids: # Update existing tracking records tracking_id = tracking_ids[(tid, k)] if tracking_id not in sql_updates: sql_updates[tracking_id] = {'id': tracking_id} # Store period, used while cleaning up old tracking records. sql_updates[tracking_id]['period'] = v['period'] sql_updates[tracking_id]['last_time'] = now if v['expired']: sql_updates[tracking_id]['init_time'] = now sql_updates[tracking_id]['cur_msgs'] = recipient_count sql_updates[tracking_id]['cur_quota'] = size else: sql_updates[tracking_id]['init_time'] = v['init_time'] sql_updates[tracking_id][ 'cur_msgs'] = 'cur_msgs + %d' % recipient_count sql_updates[tracking_id][ 'cur_quota'] = 'cur_quota + %d' % size else: # no tracking record. insert new one. # (tid, account, cur_msgs, period, cur_quota, init_time, last_time) if not (tid, k) in sql_inserts: _sql = '(%d, %s, %d, %d, %d, %d, %d)' % (tid, sqlquote( k), recipient_count, v['period'], size, now, now) sql_inserts.append(_sql) if sql_inserts: sql = """INSERT INTO throttle_tracking (tid, account, cur_msgs, period, cur_quota, init_time, last_time) VALUES """ sql += ','.join(set(sql_inserts)) logger.debug('[SQL] Insert new tracking record(s): {}'.format(sql)) conn.execute(sql) for (_tracking_id, _kv) in list(sql_updates.items()): _sql = """UPDATE throttle_tracking SET period={}, last_time={}, init_time={}, cur_msgs={}, cur_quota={} WHERE id={}""".format(_kv['period'], _kv['last_time'], _kv['init_time'], _kv['cur_msgs'], _kv['cur_quota'], _tracking_id) logger.debug('[SQL] Update tracking record: {}'.format(_sql)) conn.execute(_sql) logger.debug('[OK] Passed all {} throttle settings.'.format(throttle_type)) return SMTP_ACTIONS['default']