* Added initial logger

 * Acknowledgement time calculations now in JS
 * Updated logging to indicate where and update comes from

9 files changed, 160 insertions, 65 deletions

diff --git a/bin/mauveserver b/bin/mauveserver
index 50e1465..0f9ebac 100755
--- a/bin/mauveserver
+++ b/bin/mauveserver
@@ -34,18 +34,6 @@
 #  Patrick J Cherry <patrick@bytemark.co.uk>
 #
 
-def error(msg)
-  STDERR.print "*** Error: #{msg}\n"
-  STDERR.print "*** For help, type: #{$0} -h\n"
-
-  if msg.respond_to?("backtrace")
-    STDERR.print "*** Backtrace:\n"
-    STDERR.print msg.backtrace.join("\n")+"\n" 
-  end
-
-  exit 1
-end
-
 help = manual = verbose = version = test = false
 while arg = ARGV.pop
   case arg
@@ -95,6 +83,32 @@ puts "#{$0}: version "+Mauve::VERSION if version
 
 exit 0 if help or version or manual
 
+require 'log4r'
+
+#
+# Initial logger -- gets detroyed later.
+#
+logger      = Log4r::Logger.new 'Mauve'
+outputter   = Log4r::StderrOutputter.new("initial")
+outputter.formatter = Log4r::PatternFormatter.new( :pattern => "%d [ %6.6l ] [ %12.12c ] %m" )
+outputter.level     = verbose ? Log4r::DEBUG : Log4r::INFO
+logger.outputters   << outputter
+
+def error(msg)
+  logger = Log4r::Logger.new 'Mauve'
+  logger.error
+  logger.error "*** Error: #{msg}\n"
+  logger.error "*** For help, type: #{$0} -h\n"
+
+  if msg.respond_to?("backtrace")
+    logger.debug "*** Backtrace:\n"
+    logger.debug msg.backtrace.join("\n")+"\n" 
+  end
+
+  exit 1
+end
+
+
 begin
   eval "Proc.new { |a,&b| }"
 rescue SyntaxError => no_blocks_with_procs
@@ -119,11 +133,11 @@ require 'mauve/configuration_builders'
 begin
   Mauve::Configuration.current = Mauve::ConfigurationBuilder.load(configuration_file)
 rescue StandardError => ex
-  error (verbose ? ex : ex.to_s)
+  error ex 
 end
 
 if test
-  puts "*** Configuration looks OK!"
+  logger.info "*** Configuration looks OK!"
   exit 0 
 end
 
@@ -132,7 +146,7 @@ end
     Mauve::Server.instance.logger.warn "#{sig} signal received.  Restarting."
     Mauve::Server.instance.stop
 
-    #
+    # 
     # Reload configuration
     #
     begin
@@ -167,6 +181,7 @@ end
         l.outputters.delete(old)
       end
 
+      old.flush
       old.close
 
       Mauve::Server.instance.logger.info "Opened #{new.filename}."
@@ -183,8 +198,16 @@ end
 end
 
 begin
+  if outputter and logger.outputters.include?(outputter)
+    logger.debug "Closing initial outputter"
+    logger.outputters.delete(outputter)
+    outputter.flush
+    outputter.close
+  end
+
+  logger.info "This is mauve #{Mauve::VERSION}"
   Mauve::Server.instance.start
 rescue StandardError => ex
-  error (verbose ? ex : ex.to_s)
+  error ex 
 end
 
diff --git a/heartbeat_hammer.sh b/heartbeat_hammer.sh
index 33cbc29..12b74bc 100644
--- a/heartbeat_hammer.sh
+++ b/heartbeat_hammer.sh
@@ -1,6 +1,6 @@
 #!/bin/bash
 
-PRE="ruby -I lib bin/mauvesend localhost"
+PRE="ruby -I lib bin/mauvesend [::1]"
 F=60
 S=10
 n=$*
diff --git a/lib/mauve/alert.rb b/lib/mauve/alert.rb
index 6bde73a..027cc8c 100644
--- a/lib/mauve/alert.rb
+++ b/lib/mauve/alert.rb
@@ -91,7 +91,10 @@ module Mauve
     end
 
     alias to_s inspect
-   
+
+    #
+    # This is to stop datamapper inserting duff dates into the database.
+    #
     def check_dates
       bad_dates = self.attributes.find_all do |key, value|
         value.is_a?(DateTime) and not (DateTime.new(2000,1,1,0,0,0)..DateTime.new(2020,1,1,0,0,0)).include?(value)
@@ -225,8 +228,6 @@ module Mauve
         end
       end
 
-      logger.info "#{self.inspect} updated." unless @attributes_before_save.empty?
-
       true
     end
 
@@ -296,6 +297,7 @@ module Mauve
       raise! if (will_unacknowledge_at and will_unacknowledge_at.to_time <= MauveTime.now) or
         (will_raise_at and will_raise_at.to_time <= MauveTime.now)
       clear! if will_clear_at && will_clear_at.to_time <= MauveTime.now
+      logger.info("Polled #{self.inspect}")
     end
 
 
@@ -388,13 +390,13 @@ module Mauve
       #
       # Receive an AlertUpdate buffer from the wire.
       #
-      def receive_update(update, reception_time = MauveTime.now)
+      def receive_update(update, reception_time = MauveTime.now, ip_source="network")
 
         update = Proto::AlertUpdate.parse_from_string(update) unless update.kind_of?(Proto::AlertUpdate)
 
         alerts_updated = []
         
-        logger.debug("Alert update received from wire: #{update.inspect.split("\n").join(" ")}")
+        # logger.debug("Alert update received from wire: #{update.inspect.split("\n").join(" ")}")
         
         #
         # Transmission time helps us determine any time offset
@@ -508,6 +510,12 @@ module Mauve
           else
             alert_db.clear!
           end
+
+          #
+          # Record the fact we received an update.
+          #
+          logger.info("Received update from #{ip_source} for #{alert_db.inspect}")
+
         end
         
         # If this is a complete replacement update, find the other alerts
diff --git a/lib/mauve/configuration_builders/logger.rb b/lib/mauve/configuration_builders/logger.rb
index a1d0388..3f60dfe 100644
--- a/lib/mauve/configuration_builders/logger.rb
+++ b/lib/mauve/configuration_builders/logger.rb
@@ -48,7 +48,7 @@ module Mauve
       is_builder "outputter", LoggerOutputter
 
       def builder_setup
-        @result         = Log4r::Logger.new('Mauve')
+        @result         = Log4r::Logger['Mauve'] || Log4r::Logger.new('Mauve')
         @default_format = nil
         @default_level  = Log4r::RootLogger.instance.level
       end
@@ -92,6 +92,7 @@ module Mauve
         end
 
         result.outputters << outputter
+#        result.outputter.write("Created logger")
       end
     end
   end
diff --git a/lib/mauve/mauve_time.rb b/lib/mauve/mauve_time.rb
index 79fa4f3..812b0e2 100644
--- a/lib/mauve/mauve_time.rb
+++ b/lib/mauve/mauve_time.rb
@@ -21,7 +21,7 @@ class DateTime
   end
 
   def in_x_hours(*args)
-    self.to_s_human(*args)
+    self.to_time.in_x_hours(*args)
   end
 
 end
diff --git a/lib/mauve/processor.rb b/lib/mauve/processor.rb
index f5e8fac..059ca15 100644
--- a/lib/mauve/processor.rb
+++ b/lib/mauve/processor.rb
@@ -43,9 +43,9 @@ module Mauve
         
         Timer.instance.freeze if Timer.instance.alive? and !Timer.instance.frozen?
 
-        logger.debug("Got #{data.inspect} from #{client.inspect}")
+        # logger.debug("Got #{data.inspect} from #{client.inspect}")
 
-        ip_source = "#{client[3]}:#{client[1]}"
+        ip_source = "#{client[3]}"
         update = Proto::AlertUpdate.new
 
         begin
@@ -62,7 +62,7 @@ module Mauve
           logger.debug "Update #{update.transmission_id} sent at #{update.transmission_time} from "+
             "'#{update.source}'@#{ip_source} alerts #{update.alert.length}"
 
-          Alert.receive_update(update, received_at)
+          Alert.receive_update(update, received_at, ip_source)
 
         rescue Protobuf::InvalidWireType, 
                NotImplementedError, 
diff --git a/lib/mauve/timer.rb b/lib/mauve/timer.rb
index 8533451..1c8c37c 100644
--- a/lib/mauve/timer.rb
+++ b/lib/mauve/timer.rb
@@ -49,7 +49,7 @@ module Mauve
         #
         # La la la nothing to do.
         #
-        logger.info("Next to notify: #{next_to_notify} -- snoozing until #{next_to_notify.due_at}")
+        logger.info("Next to notify: #{next_to_notify} #{next_to_notify.is_a?(AlertChanged) ? "(reminder)" : "(heartbeat)"} -- snoozing until #{next_to_notify.due_at.iso8601}")
         sleep_loops = ((next_to_notify.due_at - MauveTime.now).to_f / 0.1).round.to_i
       end
 
diff --git a/lib/mauve/web_interface.rb b/lib/mauve/web_interface.rb
index 4bb9517..bd1ceb9 100644
--- a/lib/mauve/web_interface.rb
+++ b/lib/mauve/web_interface.rb
@@ -267,7 +267,6 @@ EOF
 
     get '/ajax/time_to_s_human/:seconds' do
       content_type :text
-
       secs = params[:seconds].to_i
       Time.at(secs).to_s_human
     end
diff --git a/static/javascript/mauve_utils.js b/static/javascript/mauve_utils.js
index 45a651d..2bea0ca 100644
--- a/static/javascript/mauve_utils.js
+++ b/static/javascript/mauve_utils.js
@@ -3,62 +3,126 @@ function updateDate() {
   //
   //  Date.getTime() returns *milliseconds*
   //
-  var this_date = workoutDate( $('#n_hours').val(), $('#type_hours').val() );
-  $('#ack_until_text').html("(until "+humanDate(this_date)+")");
-  $('#ack_until').val(this_date.getTime()/1000);
+  var this_date = workoutDate( $( '#n_hours' ).val(), $( '#type_hours' ).val() );
+  $( '#ack_until' ).val( this_date.getTime()/1000 );
+
+  // 
+  // Use a asynchronous ajax convert a date to a human string.  NB Date.getTime()
+  // returns *milliseconds*
+  //
+  $.ajax( {
+    url:     '/ajax/time_to_s_human/'+this_date.getTime()/1000, 
+    timeout: 1000,
+    success: function( data )  { $( '#ack_until_text' ).html( "( until "+data+" )" ); },
+    error:   function( a,b,c ) { $( '#ack_until_text' ).html( "( until "+this_date.toString()+" )" ); }
+  } );
 
   return false;
 }
 
-function workoutDate(h, t) {
-  var new_date = null;
+function workoutDate( h, type ) {
 
-  h = new Number(h);
-  h = ( h > 300 ? 300 : h );
+  n = new Number( h );
+  n *= 3600 * 1000;
 
-  // 
-  // Use a synchronous ajax request to fetch the date.  Note that
-  // Date.getTime() returns milliseconds..
+  if ( type == null ) {
+    type = "wallclock" ;
+  }
+
+  var step = 3600 * 1000;
   //
-  $.ajax({
-    url: '/ajax/time_in_x_hours/'+h+"/"+t,
-    async: false,
-    success: function(data) { new_date = new Date ( new Number(data) * 1000 ); }
-  });
+  // Get the time now, in milliseconds
+  //
+  var d    = new Date();
+  var t    = d.getTime();
+  //
+  // Can't ack longer than a week
+  //
+  var maxDate = new Date( d.getTime() + 1000 * 86400 * 8 )
 
-  return new_date;
-}
 
+  //
+  // Work out how much time to subtract now
+  //
+  while ( n >= 0 && t < maxDate.getTime() ) {
+    //
+    // If we're currently OK, and we won't be OK after the next step ( or
+    // vice-versa ) decrease step size, and try again
+    //
+    if ( doTimeTest( t, type ) != doTimeTest( t+step, type ) ) {
+      //
+      // Unless we're on the smallest step, try a smaller one.
+      //
+      if ( step > 1000 ) {
+        step /= 60;
+
+      } else {
+        if ( doTimeTest( t, type ) ) n -= step;
+        t += step;
+
+        //
+        // Set the step size back to an hour
+        //
+        step = 3600*1000;
+      }
 
-function humanDate(d) {
-  var new_date = null;
+      continue;
+    } 
 
-  if ( d == null ) {
-    d = new Date();
+    //
+    // Decrease the time by the step size if we're currently OK.
+    //
+    if ( doTimeTest( t, type ) ) n -= step;
+    t += step;
   }
 
-  // 
-  // Use a synchronous ajax convert a date to a human string.  NB Date.getTime()
-  // returns *milliseconds*
   //
-  $.ajax({
-    url: '/ajax/time_to_s_human/'+d.getTime()/1000, 
-    async: false,
-    success: function(data) { new_date = data; }
-  });
+  // Substract any overshoot.
+  //
+  if ( n < 0 ) t += n;
 
-  return new_date;
+  //
+  // Make sure we can't ack alerts too far in the future.
+  //
+  return ( t > maxDate.getTime() ? maxDate : new Date( t ) );
 }
 
-function fetchDetail(a) {
+function fetchDetail( a ) {
   // Use a synchronous ajax request to fetch the date.
-  $.get('/ajax/alerts_table_alert_detail/'+a,
-    function(data) { 
-      $('#tr_summary_'+a).after(data);
+  $.get( '/ajax/alerts_table_alert_detail/'+a,
+    function( data ) { 
+      $( '#tr_summary_'+a ).after( data );
       // Only fetch the data once.
-      $('#a_detail_'+a).attr("onclick",null).click(function() { $('#tr_detail_'+a).toggle(); return false; });
-  });
+      $( '#a_detail_'+a ).attr( "onclick",null ).click( function() { $( '#tr_detail_'+a ).toggle(); return false; } );
+  } );
 
   return false;
 }
 
+//
+// This expects its arguments as a time in milliseconds, and a type of "working", "daytime", or something else.
+//
+function doTimeTest( t, type ) {
+  
+  var d = new Date( t );
+  var r = false;
+
+  switch ( type ) {
+    case "working":
+      r = ( d.getDay() > 0 && d.getDay() < 6 && 
+          ( ( d.getHours() >= 9 && d.getHours() <= 16 ) || 
+            ( d.getHours() == 8 && d.getMinutes() >= 30 ) 
+          ) );
+      break;
+
+    case "daytime":
+      r = ( d.getHours() >= 8 && d.getHours() <= 21 );
+      break;
+
+    default:
+      r = true;
+  } 
+
+  return r;
+}
+