--- relaydelay.pl	2004/05/02 16:57:14	1.1
+++ relaydelay.pl	2004/05/02 17:56:32
@@ -35,6 +35,7 @@
 use Socket;
 use POSIX qw(strftime);
 use Errno qw(ENOENT);
+use Sys::Syslog;
 
 use DB_File;
 use DBI;
@@ -55,6 +56,7 @@
 # If you do/don't want to see debugging messages printed to stdout,
 #   then set this appropriately.
 my $verbose = 1;
+$|=1; # Make STDOUT logs flush faster
 
 # Database connection params
 my $database_type = 'mysql';
@@ -245,10 +247,13 @@
 sub db_connect($) {
   my $verbose = shift;
 
-  return $global_dbh if (defined $global_dbh);
+  if (defined($global_dbh)) {
+    return $global_dbh if ($global_dbh->ping);
+  }
 
   my $dsn = "DBI:$database_type:database=$database_name:host=$database_host:port=$database_port";
   print "DBI Connecting to $dsn\n" if $verbose;
+  syslog('info',"DBI connecting to $dsn");
 
   # Note: We do all manual error checking for db errors
   my $dbh = DBI->connect($dsn, $database_user, $database_pass, 
@@ -387,7 +392,7 @@
 
   print "  IN EOM CALLBACK - PrivData: " . ${$privdata_ref} . "\n" if ($verbose);
 
-  my $dbh = db_connect(0) or goto DB_FAILURE;
+  my $dbh = db_connect($verbose) or goto DB_FAILURE;
 
   # parse and store the data
   my $rowids;
@@ -467,6 +472,21 @@
 {
   my $ctx = shift;
 
+  # Get the queue ID for logging
+  my $queue_id    = $ctx->getsymval("{i}");
+  if (!defined($queue_id)) { $queue_id="no-queue-id"; }
+
+  # Get the remote hostname and ip in the form "[ident@][hostname] [ip]"
+  my $tmp = $ctx->getsymval("{_}");  
+  my ($relay_ip, $relay_name, $relay_ident, $relay_maybe_forged);
+  if ($tmp =~ /\A(\S*@|)(\S*) ?\[(.*)\]( \(may be forged\)|)\Z/) {
+    $relay_ident = $1;
+    $relay_name = $2;
+    $relay_ip = $3;
+    $relay_maybe_forged = (length($4) > 0 ? 1 : 0);
+  }
+  $relay_ip = "no-ip-available" if (!defined($relay_ip));
+
   # Get our status and check to see if we need to do anything else
   my $privdata_ref = $ctx->getpriv();
   # Clear our private data on this context (but only if was set previously)
@@ -490,7 +510,7 @@
   #   (this means we didn't expect/cause an abort, but something else did)
   if (substr($rowids, 0, 1) ne '0') {
     # Ok, we need to update the db, so get a handle
-    my $dbh = db_connect(0) or goto DB_FAILURE;
+    my $dbh = db_connect($verbose) or goto DB_FAILURE;
   
     # split up the rowids and update each in turn
     my @rowids = split(",", $rowids);
@@ -506,6 +526,7 @@
       my $rows = $dbh->do("UPDATE relaytofrom SET record_expires = NOW() "
         . " WHERE id = $rowid AND origin_type = 'AUTO' AND passed_count = 0") or goto DB_FAILURE;
       if ($rows > 0) {
+        syslog('info',"$queue_id: message aborted, no good deliveries, exiring #%d: [%s] %s %s",$rowid, $relay_ip, $mail_from, $rcpt_to);
         print "  * Mail record had no successful deliveries.  Expired record on rowid $rowid.\n" if ($verbose);
       }
     }
@@ -537,9 +558,10 @@
 #   necessary, but they'll age off fairly quickly.
 # If any sql calls fail, we either ignore them or simply return, since these 
 #   updates aren't critical to the mail handling process.
-sub reverse_track($$$)
+sub reverse_track($$$$)
 {
   my $dbh = shift;
+  my $queue_id = shift;
   my $mail_from = shift;
   my $rcpt_to = shift;
 
@@ -548,7 +570,10 @@
   # Note the reversed from and to fields! 
   $sth->execute($rcpt_to, $mail_from) or return;
   my $rowid = $sth->fetchrow_array();
-  my $nextrowid = $sth->fetchrow_array();
+  my $nextrowid;
+  if (defined($rowid)) {
+    $nextrowid = $sth->fetchrow_array();
+  }
   $sth->finish();
 
   if (defined($rowid) and !defined($nextrowid)) {
@@ -566,11 +591,10 @@
   # Note the reversed from and to fields! 
   $sth->execute($rcpt_to, $mail_from);
   $sth->finish;
-  if ($verbose) {
-    # Get the rowid for the debugging message
-    $rowid = $dbh->selectrow_array("SELECT LAST_INSERT_ID()") and
-      print "  Reverse tracking row successfully inserted for the recipient of this mail.  rowid: $rowid\n";
-  }
+  # Get the rowid for the debugging message
+  $rowid = $dbh->selectrow_array("SELECT LAST_INSERT_ID()") and
+  syslog('info',"$queue_id: reverse record created for outgoing mail, #%d: %s %s",$rowid, $mail_from, $rcpt_to);
+  print "  Reverse tracking row successfully inserted for the recipient of this mail.  rowid: $rowid\n" if ($verbose);
 }
 
 
@@ -614,7 +638,7 @@
   print "Passed Recipient: $rcpt_to\n" if ($verbose);
 
   # Get the database handle (after got the privdata)
-  my $dbh = db_connect(0) or goto DB_FAILURE;
+  my $dbh = db_connect($verbose) or goto DB_FAILURE;
   
   #print "my_envrcpt:\n";
   #print "   + args: '" . join(', ', @args) . "'\n";
@@ -670,6 +694,16 @@
     }
   }
 
+  # Only do our processing if the mail client is not authenticated in some way
+  if (defined($authen) and $authen ne "")
+  {
+    syslog('info',"$queue_id: SMTP AUTH: $authen");
+    print "  AuthType: $authtype - Credentials: $authen\n" if ($verbose);
+    print "  Mail delivery is authenticated.  Skipping checks.\n" if ($verbose);
+    reverse_track($dbh, $queue_id, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
+    goto PASS_MAIL;
+  }
+
 
   # Generate all the subparts of relay_ip, mail_from, rcpt_to, and relay_name for later checks
   my @relay_ip_parts;
@@ -749,12 +783,17 @@
 
     if (defined $rowid) {
       if ($blacklisted) {
+        syslog('info',"$queue_id: Blacklisted relay: $relay_ip entry #$rowid");
         print "  Blacklisted Relay.  Skipping checks and rejecting the mail.  rowid: $rowid\n" if ($verbose);
         goto DELAY_MAIL;
       }
       if ($whitelisted) {
+        syslog('info',"$queue_id: Whitelisted relay: $relay_ip entry #$rowid");
         print "  Whitelisted Relay.  Skipping checks and passing the mail.  rowid: $rowid\n" if ($verbose);
-        reverse_track($dbh, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
+#        Don't reverse_track here, otherwise all remote whitelisted IPs
+#        will cause each message sender/recip pair to have a row added to
+#        the database, commented till I can chat with the Author:
+#        reverse_track($dbh, $queue_id, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
         goto PASS_MAIL;
       }
     }
@@ -785,10 +824,12 @@
 
     if (defined $rowid) {
       if ($blacklisted) {
+        syslog('info',"$queue_id: Blacklisted RCPT: $rcpt_to entry #$rowid");
         print "  Blacklisted Recipient.  Skipping checks and rejecting the mail.  rowid: $rowid\n" if ($verbose);
         goto DELAY_MAIL;
       }
       if ($whitelisted) {
+        syslog('info',"$queue_id: Whitelisted RCPT: $rcpt_to entry #$rowid");
         print "  Whitelisted Recipient.  Skipping checks and passing the mail.  rowid: $rowid\n" if ($verbose);
         goto PASS_MAIL;
       }
@@ -821,10 +862,12 @@
 
     if (defined $rowid) {
       if ($blacklisted) {
+        syslog('info',"$queue_id: Blacklisted sender: %s entry #%d", $mail_from, $rowid);
         print "  Blacklisted Sender.  Skipping checks and rejecting the mail.  rowid: $rowid\n" if ($verbose);
         goto DELAY_MAIL;
       }
       #if ($whitelisted) {
+        syslog('info',"$queue_id: Whitelisted sender (ignored): %s entry #%d",$mail_from, $rowid);
       #  print "  Whitelisted Sender.  Skipping checks and passing the mail.  rowid: $rowid\n" if ($verbose);
       #  goto PASS_MAIL;
       #}
@@ -843,23 +886,14 @@
   if (($mail_mailer !~ /smtp\Z/i) and ($mail_mailer !~ /\Alocal\Z/i)) {
     # we aren't using an smtp-like mailer, so bypass checks
     print "  Mail delivery is not using an smtp-like mailer.  Skipping checks.\n" if ($verbose);
-    reverse_track($dbh, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
+    reverse_track($dbh, $queue_id, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
     goto PASS_MAIL;
   }
 
   # Check to see if the mail is looped back on a local interface and skip checks if so
   if ($ifaddr eq $relay_ip) {
     print "  Mail delivery is sent from a local interface.  Skipping checks.\n" if ($verbose);
-    reverse_track($dbh, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
-    goto PASS_MAIL;
-  }
-
-  # Only do our processing if the mail client is not authenticated in some way
-  if (defined($authen) and $authen ne "")
-  {
-    print "  AuthType: $authtype - Credentials: $authen\n" if ($verbose);
-    print "  Mail delivery is authenticated.  Skipping checks.\n" if ($verbose);
-    reverse_track($dbh, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
+    reverse_track($dbh, $queue_id, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
     goto PASS_MAIL;
   }
 
@@ -897,6 +931,8 @@
           last;
         }
       }
+      syslog('info',"$queue_id: Whitelisted relay from access.db: $relay_ip")
+        if ($bypass_checks);
       print "  Whitelisted Relay match found in ACCESS DB.  Skipping checks and passing the mail.\n" 
         if ($verbose and $bypass_checks);
 
@@ -913,6 +949,8 @@
             last;
           }
         }
+        syslog('info',"$queue_id: Whitelisted recipient from access.db: $rcpt_to")
+          if ($bypass_checks);
         print "  Whitelisted Recipient match found in ACCESS DB.  Skipping checks and passing the mail.\n" 
           if ($verbose and $bypass_checks);
       }
@@ -921,7 +959,7 @@
 
       untie %accessdb;
       if ($bypass_checks) {
-        reverse_track($dbh, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
+        reverse_track($dbh, $queue_id, $mail_from, $rcpt_to) if ($reverse_mail_tracking and $rcpt_mailer !~ /\Alocal\Z/i);
         goto PASS_MAIL;
       }
     }
@@ -962,6 +1000,7 @@
 
   if (defined $rowid) {
     if ($block_expired) {
+      syslog('info',"$queue_id: triplet known and block expired, passing for #%d: [%s] %s %s", $rowid, $relay_ip, $mail_from, $rcpt_to);
       print "  Email is known and block has expired.  Passing the mail.  rowid: $rowid\n" if ($verbose);
       # If this record is a reverse tracking record with unknown IP, then 
       #   update it to include the now-known IP (if tracking is enabled)
@@ -975,6 +1014,7 @@
     }
     else {
       # the email is known, but the block has not expired.  So return a tempfail.
+      syslog('info',"$queue_id: triplet known but block still active, TEMPFAIL for #%d: [%s] %s %s", $rowid, $relay_ip, $mail_from, $rcpt_to);
       print "  Email is known but block has not expired.  Issuing a tempfail.  rowid: $rowid\n" if ($verbose);
       goto DELAY_MAIL;
     }
@@ -996,11 +1036,13 @@
   $rowid = $dbh->selectrow_array("SELECT LAST_INSERT_ID()");
     
   if ($delay_mail_secs == 0) {
+    syslog('info',"$queue_id: triplet never seen, but delay=0, inserting #%d: [%s] %s %s", $rowid, $relay_ip, $mail_from, $rcpt_to);
     print "  New mail row successfully inserted.  Passing mail.  rowid: $rowid\n" if ($verbose);
     # and now jump to normal blocking actions
     goto PASS_MAIL;
   }
 
+  syslog('info',"$queue_id: triplet never seen, inserting #%d: [%s] %s %s", $rowid, $relay_ip, $mail_from, $rcpt_to);
   print "  New mail row successfully inserted.  Issuing a tempfail.  rowid: $rowid\n" if ($verbose);
   # and now jump to normal blocking actions
   goto DELAY_MAIL;
@@ -1183,6 +1225,10 @@
     close PIDF;
   }
 
+  # Open syslog socket
+  openlog("greylist", 'cons,pid', 'mail');
+  syslog('info', "Greylist initializing");
+
   if (defined $sendmail_accessdb_file) {
     my %accessdb;
     # Test that we can open the accessdb file
@@ -1230,6 +1276,7 @@
   }
 
   print "Starting Sendmail::Milter $Sendmail::Milter::VERSION engine.\n";
+  syslog('info',"Starting Sendmail::Milter $Sendmail::Milter::VERSION engine.");
 
   # Parameters to main are max num of interpreters, num requests to service before recycling threads
   # We don't set it to recycle children, as that seems to cause coredumps.
