]> git.8kb.co.uk Git - slony-i/pgbouncer_follower/blob - pgbouncer_follower.pl
Changes:
[slony-i/pgbouncer_follower] / pgbouncer_follower.pl
1 #!/usr/bin/perl
2
3 # Script:   pgbouncer_follower.pl
4 # Copyright:    22/04/2012: v1.0.1 Glyn Astill <glyn@8kb.co.uk>
5 # Requires: Perl 5.10.1+, PostgreSQL 9.0+ Slony-I 2.0+
6 #
7 # This script is a command-line utility to monitor Slony-I clusters
8 # and reconfigure pgbouncer to follow replication sets.
9 #
10 # This script is free software: you can redistribute it and/or modify
11 # it under the terms of the GNU General Public License as published by
12 # the Free Software Foundation, either version 3 of the License, or
13 # (at your option) any later version.
14 #
15 # This script is distributed in the hope that it will be useful,
16 # but WITHOUT ANY WARRANTY; without even the implied warranty of
17 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
18 # GNU General Public License for more details.
19 #
20 # You should have received a copy of the GNU General Public License
21 # along with this script.  If not, see <http://www.gnu.org/licenses/>.
22
23 use strict;
24 use warnings;
25 use DBI;
26 use v5.10.1;
27 use Getopt::Long qw/GetOptions/;
28 use Digest::MD5 qw/md5 md5_hex md5_base64/;
29 use Sys::Hostname;
30 use IO::Socket;
31 use Time::HiRes qw/usleep/;
32 use sigtrap 'handler' => \&cleanExit, 'HUP', 'INT','ABRT','QUIT','TERM';
33 Getopt::Long::Configure qw/no_ignore_case/;
34
35 use vars qw{%opt};
36
37 use constant false => 0;
38 use constant true  => 1;
39
40 my $g_usage = 'Pass configuration file: pool_follower.pl -f <configuration_path> [-D]  ';
41 my $g_debug = false;
42 my $g_pidfile = "/tmp/pgbouncer_follower_%mode.pid";
43 my $g_logfile = "/tmp/pgbouncer_follower_%mode.log";
44 my $g_poll_interval = 1000;
45 my $g_user = "slony";
46 my $g_pass;
47 my $g_clname = "replication";
48 my $g_clsets = "1";
49 my @g_conninfos;
50 my @g_cluster;                  # no_id, no_comment, no_prov, orig_sets, conninfo, dbname, host, port
51 my $g_status_file = "/tmp/pgbouncer_follower_%mode.status";
52 my $g_conf_template = "/etc/pgbouncer/pgbouncer_%mode.template";
53 my $g_conf_target = "/etc/pgbouncer/pgbouncer_%mode.ini";
54 my $g_reload_command = "/etc/init.d/pgbouncer_%mode reload";
55 my $g_mode = 'rw';
56 my $g_all_databases=false;
57 my ($year, $month, $day, $hour, $min, $sec);
58 my $change_time;
59 my $g_host = hostname;
60 my ($g_addr)=inet_ntoa((gethostbyname(hostname))[4]);
61 my $g_origins_only = false;
62 my $g_best_config = false;
63 my $g_max_lag = 0;
64
65 die $g_usage unless GetOptions(\%opt, 'config_file|f=s', 'daemon|D',) and keys %opt and ! @ARGV;
66
67 unless (getConfig($opt{config_file})){
68     print ("There was a problem reading the configuration.\n");
69 }
70  
71 if ($g_debug) {
72     printLogLn($g_logfile, "DEBUG: Logging to my '$g_logfile'");
73     printLogLn($g_logfile, "\t Watching sets $g_clsets in Slony-I cluster '$g_clname' polling every ${g_poll_interval}ms"); 
74     printLogLn($g_logfile, "\t Following " . ($g_all_databases ? "all databases" : "replicated database only") . " on an '$g_mode' node for the above replicated sets");
75     printLogLn($g_logfile, "\t Template config '$g_conf_template' Target config '$g_conf_target'");
76     printLogLn($g_logfile, "\t Reload command is '$g_reload_command'");
77     printLogLn($g_logfile, "\t Status stored in '$g_status_file'");
78     printLogLn($g_logfile, "\t Using local address for '$g_host' as '$g_addr'");
79     if (($g_max_lag > 0) && ($g_mode = 'ro')) {
80         printLogLn($g_logfile, "\t Max lag for read only targets will be $g_max_lag seconds");
81     }
82     #printLogLn($g_logfile, "\t '$g_user' as '$g_pass'");
83 }
84
85 if (defined($opt{daemon})) {
86     printLogLn($g_logfile, "pgbouncer_follower starting up");   
87     if (writePID($g_pidfile)) {
88         while (true) {
89             doAll();
90             if ($g_debug) {
91                 printLogLn($g_logfile, "DEBUG: Sleeping for ${g_poll_interval}ms");
92             }
93             usleep($g_poll_interval * 1000);
94         }
95     }
96 }
97 else {
98     doAll();
99 }
100
101 cleanExit(0);
102
103 sub cleanExit {
104     if (defined($opt{daemon})) {
105         printLogLn($g_logfile, "pgbouncer_follower shutting down");    
106         removePID($g_pidfile);
107     }
108     exit(0);
109 }
110
111 sub doAll {
112     my $node_to;
113     my $conninfo_read = 0;
114
115     foreach my $conninfo (@g_conninfos) {
116         $conninfo_read++;
117         eval {
118             @g_cluster = loadCluster($g_clname, $conninfo, $g_user, $g_pass, $g_addr, $g_clsets);
119             if ($g_debug) {
120                 printLogLn($g_logfile, "DEBUG: ($conninfo_read) Cluster with " . scalar(@g_cluster) . " nodes read from conninfo: $conninfo");
121                 foreach (@g_cluster) {
122                     printLogLn($g_logfile, "DEBUG: Node #" . @$_[0] . " DETAIL: " . @$_[1] . " " . @$_[2] . " " . (@$_[3] // "<NONE>") . " " . @$_[4] . " " . (@$_[5] // "<NONE>") . " " . @$_[6] . " " . @$_[7] . " " . @$_[8] . " " . @$_[9] . " " . @$_[10] . " "  . @$_[11]);
123                 }
124             }
125         };
126         if ($@) {
127             printLogLn($g_logfile, "ERROR: Failed using conninfo: $conninfo DETAIL: $@");
128         }
129         elsif($g_best_config) {
130             if ($g_debug) {
131                 printLogLn($g_logfile, "DEBUG: Found current origin to read config from");
132             }
133             last;
134         } 
135     }
136     unless (checkCluster($g_status_file)) {
137         if ($g_debug) {
138              printLogLn ($g_logfile, "DEBUG: Cluster status unchanged");
139         }
140     }
141     else {
142         printLogLn ($g_logfile, "Cluster status changed");
143         $node_to = generateConfig($g_conf_template, $g_conf_target, $g_mode, $g_all_databases, $g_clsets);
144         if (reloadConfig($g_reload_command)) {
145             printLogLn ($g_logfile, "Pool repointed to node #$node_to");
146         }
147     }
148 }
149
150 sub reloadConfig {
151     my $reload_command = shift;
152     my $success = true;
153     if(length($reload_command // '')) {
154         printLogLn($g_logfile, "Running '$reload_command'");
155         eval {
156             open(RELOAD, "-|", $reload_command . " 2>&1");
157             while (<RELOAD>) {
158                 printLogLn($g_logfile, $_);
159             }
160             close(RELOAD);
161             printLogLn($g_logfile, "Reload command has been run.");
162         };
163         if ($@) {
164             printLogLn($g_logfile, "ERROR: Failed to run reload command DETAIL: $@");
165             $success = false;
166         }
167     }
168     return $success;
169 }
170
171 sub generateConfig {
172     my $template = shift;
173     my $target = shift;
174     my $mode = shift;
175     my $all_databases = shift;
176     my $clsets = shift;
177
178     my $success = false;
179     my @sets_to_follow;
180     my @sets_origin;
181     my @sets_subscribed;
182     my $target_node_id;
183     my $target_db;
184     my $target_host;
185     my $target_sets;
186     my $target_port = 5432;
187     my $target_is_origin;
188
189     if ($g_debug) {
190         printLogLn($g_logfile, "DEBUG: All databases = " . ($g_all_databases ? 'true' : 'false'));
191     }
192
193     if (open(INFILE, "<", $template)) {
194         if (open(OUTFILE, ">", $target)) {
195             print OUTFILE "# Configuration file autogenerated at " . getRuntime() . " from $template\n";
196             foreach (<INFILE>) {
197                if (m/\[databases]/) {
198
199                     # Try and choose a node; we always assign the origin initially regardless of rw/ro status
200                     # when in ro mode and if we then  find a suitable subscriber we'll reassign to it.
201                     foreach my $node (@g_cluster) {
202                        
203
204                         # If the node is lagging anyway skip it 
205                         if (($g_mode eq 'ro') && ($g_max_lag > 0) && ($node->[11])) {
206                             printLogLn ($g_logfile, "Lag on node $node->[0] exceeds $g_max_lag seconds");
207                             next;
208                         }
209
210                         if ($clsets ne 'all') {
211                             @sets_to_follow = split(',', $clsets);
212                             if (defined($node->[3])) {
213                                 @sets_origin =  split(',', $node->[3]);
214                             }
215                             else {
216                                 undef @sets_origin;
217                             }
218                             if (defined($node->[5])) {
219                                 @sets_subscribed =  split(',', $node->[5]);
220                             }
221                             else {
222                                 undef @sets_subscribed;
223                             }
224                         }
225
226                         if (($clsets eq 'all' && defined($node->[3])) || (@sets_to_follow && @sets_origin && checkProvidesAllSets(\@sets_to_follow, \@sets_origin))) {
227                             if (defined($node->[8])) {
228                                 $target_db = $node->[7];
229                                 $target_host = $node->[8];
230                                 $target_node_id = $node->[0];
231                                 $target_sets = $node->[3];
232                                 $target_is_origin = true;
233                             }
234                             if (defined($node->[9])) {
235                                 $target_port = $node->[9];
236                             }
237                             if ($mode eq "rw") {
238                                 last;
239                             }
240                         }
241                         elsif (($mode eq "ro") && (($clsets eq 'all') || (@sets_to_follow && @sets_subscribed && checkProvidesAllSets(\@sets_to_follow, \@sets_subscribed)))) {    
242                             if (defined($node->[8])) {
243                                 $target_db = $node->[7];
244                                 $target_host = $node->[8];
245                                 $target_node_id = $node->[0];
246                                 $target_sets = ($node->[5] // $node->[3]);
247                                 $target_is_origin = false;
248                             }
249                             if (defined($node->[9])) {
250                                 $target_port = $node->[9];
251                             }
252                             last;
253                         }
254                     }
255                     if (defined($target_host)) {
256                         $_ = "# Configuration for " . ($target_is_origin ? "origin" : "subscriber") . " of sets $target_sets node #$target_node_id $target_host:$target_port\n" . $_;
257                         if ($g_debug) {
258                             printLogLn ($g_logfile, "DEBUG: Configuration for " . ($target_is_origin ? "origin" : "subscriber") . " of sets $target_sets node #$target_node_id $target_host:$target_port");
259                         }
260                         if ($all_databases) {
261                             $_ =~ s/(\[databases\])/$1\n\* = host=$target_host port=$target_port/;
262                         }
263                         else {
264                             $_ =~ s/(\[databases\])/$1\n$target_db = host=$target_host port=$target_port dbname=$target_db/;
265                         }
266                     }
267                     else {
268                             $_ = "# Could not find any node providing sets $g_clsets in mode $mode\n";
269                             printLogLn ($g_logfile, "DEBUG: Could not find any node providing sets $g_clsets in mode $mode");
270                     }
271                     
272                } 
273                print OUTFILE $_;
274             }
275             close (OUTFILE); 
276         }
277         else {
278             print ("ERROR: Can't open file $target\n");
279         }
280         close(INFILE);
281     }
282     else {
283         print ("ERROR: Can't open file $template\n");
284     }
285     return $target_node_id;
286 }
287
288 sub checkCluster {
289     my $infile = shift;
290     my $changed = false;
291     my $current_cluster;
292     my $previous_cluster;
293     foreach (@g_cluster) {
294         if (!$g_origins_only || defined($_->[3])) {
295             $current_cluster = md5_hex(($current_cluster // "") . $_->[0] . $_->[2] . (defined($_->[3]) ? 't' : 'f') . $_->[6] . $_->[11]);
296             if ($g_debug) {
297                 printLogLn($g_logfile, "DEBUG: Node " . $_->[0] . " detail = " . $_->[2] . (defined($_->[3]) ? 't' : 'f') . $_->[6] . $_->[11]);
298             }
299         }
300     }
301    
302     if (-f $infile) {
303         if (open(CLUSTERFILE, "<", $infile)) {
304             $previous_cluster = <CLUSTERFILE>;
305             close(CLUSTERFILE);
306         }
307         else {
308             printLogLn ($g_logfile, "ERROR: Can't open file $infile for reading");
309         }
310     }
311
312     unless (-f $infile && ($current_cluster eq $previous_cluster)) {
313         if ($g_debug) {
314                 printLogLn($g_logfile, "DEBUG: Writing to status file");
315         }
316         if (open(CLUSTERFILE, ">", $infile)) {
317             print CLUSTERFILE $current_cluster;
318             close(CLUSTERFILE);
319         }
320         else {
321             printLogLn ($g_logfile, "ERROR: Can't open file $infile for writing");
322         }
323     }
324
325     if ((($previous_cluster // "") ne "") && (($current_cluster // "") ne "") && ($current_cluster ne $previous_cluster)){
326         $changed = true;
327     }
328
329     return $changed
330 }
331
332 sub loadCluster {
333     my $clname = shift;
334     my $conninfo = shift;
335     my $dbuser = shift;
336     my $dbpass = shift;
337     my $addr = shift;
338     my $clsets = shift;
339     my $param_on = 1;
340
341     my $dsn;
342     my $dbh;
343     my $sth;
344     my $query;
345     my $version;
346     my $qw_clname;
347     my @cluster;
348
349     $g_best_config = false;
350     $dsn = "DBI:Pg:$conninfo};";
351
352     eval {
353         $dbh = DBI->connect($dsn, $dbuser, $dbpass, {RaiseError => 1});
354         $qw_clname = $dbh->quote_identifier("_" . $clname);
355
356         $query = "SELECT $qw_clname.getModuleVersion()";
357         $sth = $dbh->prepare($query);
358         $sth->execute();
359         ($version) = $sth->fetchrow; 
360         $sth->finish;
361
362         $query = "WITH x AS (
363                 SELECT a.no_id, 
364                     a.no_comment, 
365                     COALESCE(b.sub_provider, 0) AS no_prov, 
366                     NULLIF(array_to_string(array(SELECT set_id FROM $qw_clname.sl_set WHERE set_origin = a.no_id" .
367                     ($clsets ne "all" ? " AND set_id IN (" . substr('?, ' x scalar(split(',', $clsets)), 0, -2) . ")" : "") 
368                     . " ORDER BY set_id), ','), '') AS origin_sets,
369                     CASE " . ((substr($version,0,3) >= 2.2) ? "WHEN a.no_failed THEN 'FAILED' " : "") . "WHEN a.no_active THEN 'ACTIVE' ELSE 'INACTIVE' END AS no_status,
370                     string_agg(CASE WHEN b.sub_receiver = a.no_id AND b.sub_forward AND b.sub_active" .
371                     ($clsets ne "all" ? " AND b.sub_set IN (" . substr('?, ' x scalar(split(',', $clsets)), 0, -2) . ")" : "") 
372                     . " THEN b.sub_set::text END, ',' ORDER BY b.sub_set) AS prov_sets,
373                     COALESCE(c.pa_conninfo,(SELECT pa_conninfo FROM $qw_clname.sl_path WHERE pa_server = $qw_clname.getlocalnodeid(?) LIMIT 1)) AS no_conninfo
374                 FROM $qw_clname.sl_node a
375                 LEFT JOIN $qw_clname.sl_subscribe b ON a.no_id = b.sub_receiver AND b.sub_set <> 999 
376                 LEFT JOIN $qw_clname.sl_path c ON c.pa_server = a.no_id AND c.pa_client = $qw_clname.getlocalnodeid(?)
377                 LEFT JOIN $qw_clname.sl_set d ON d.set_origin = a.no_id
378                 GROUP BY b.sub_provider, a.no_id, a.no_comment, c.pa_conninfo, a.no_active
379                 ORDER BY (COALESCE(b.sub_provider, 0) = 0) DESC, a.no_id ASC
380                 ), z AS (
381                 SELECT x.*,  
382                     CASE WHEN x.no_conninfo ilike '%dbname=%' THEN(regexp_matches(x.no_conninfo, E'dbname=(.+?)\\\\M', 'ig'))[1] END AS database,
383                     CASE WHEN x.no_conninfo ilike '%host=%' THEN(regexp_matches(x.no_conninfo, E'host=(.+?)(?=\\\\s|\$)', 'ig'))[1] END AS host,
384                     CASE WHEN x.no_conninfo ilike '%port=%' THEN(regexp_matches(x.no_conninfo, E'port=(.+?)\\\\M', 'ig'))[1] ELSE '5432' END AS port,
385                     (no_id = $qw_clname.getlocalnodeid(?)) AS this_node,
386                     COALESCE((? BETWEEN 1 AND extract(epoch from s.st_lag_time)),false) AS lag_exceeded
387                 FROM x 
388                 LEFT JOIN $qw_clname.sl_status s ON s.st_received = x.no_id
389                 )
390                 SELECT * FROM z 
391                 ORDER BY origin_sets, @(CASE WHEN (host ~ '^[0-9]{1,3}(.[0-9]{1,3}){3}\$') THEN host::inet ELSE '255.255.255.255'::inet END - ?::inet) ASC";
392
393         if ($g_debug) { 
394 #            printLogLn($g_logfile, "DEBUG: " . $query);
395         }
396
397         $sth = $dbh->prepare($query);
398
399         if ($clsets ne "all") {
400             for (0..1) { 
401                 foreach my $param (split(",", $clsets)) {
402                     $sth->bind_param($param_on, $param);
403                     $param_on++;
404                 } 
405             }
406         }
407         # This param is taken 3 times
408         for (0..2) {
409             $sth->bind_param($param_on, "_" . $clname);
410             $param_on++;
411         }
412         $sth->bind_param($param_on, $g_max_lag);
413         $param_on++;
414         $sth->bind_param($param_on, (isInet($addr) ? $addr : '255.255.255.255'));
415         $sth->execute();
416
417         while (my @node = $sth->fetchrow) {
418             # If some origin sets exist for this node row (we can assume they're the sets we're following since they're filtered in the query)
419             # and the row is flagged as this_node then we have found the best node to read the configuration from.
420             if (defined($node[3]) && $node[10]) {
421                 $g_best_config = true;
422             }
423             push(@cluster,  \@node);
424         }
425
426         $sth->finish;
427         $dbh->disconnect();
428     };
429     if ($@) { 
430         printLogLn($g_logfile, "ERROR: Failed to execute query against Postgres server: $@");
431     }
432
433     return @cluster;
434 }
435
436 sub getConfig {
437     my @fields;
438     my $success = false;
439     my $infile = shift;
440     my $value;
441
442     if (open(CFGFILE, "<", $infile)) {
443         foreach (<CFGFILE>) {
444             chomp $_;
445             for ($_) {
446                 s/\r//;
447                 #s/\#.*//;
448                 s/#(?=(?:(?:[^']|[^"]*+'){2})*+[^']|[^"]*+\z).*//;
449             } 
450             if (length(trim($_))) {
451                 @fields = split('=', $_, 2);
452                 $value = qtrim(trim($fields[1]));
453                 given(lc($fields[0])) {
454                     when(/\bdebug\b/i) {
455                         $g_debug = checkBoolean($value);
456                     }
457                     when(/\bpid_file\b/i) {
458                         $g_pidfile = $value;
459                     }
460                     when(/\blog_file\b/i) {
461                         $g_logfile = $value;
462                     }
463                     when(/\bslony_user\b/i) {
464                         $g_user = $value;
465                     }
466                     when(/\bslony_pass\b/i) {
467                         $g_pass = $value;
468                     }
469                     when(/\bslony_cluster_name\b/i) {
470                         $g_clname = $value;
471                     }
472                     when(/\bslony_sets_to_follow\b/i) {
473                         $g_clsets = $value;
474                     }
475                     when(/\bserver_conninfo\b/i) {
476                         push(@g_conninfos, $value);
477                     }
478                     when(/\bfollower_poll_interval\b/i) {
479                         $g_poll_interval = checkInteger($value);
480                     }
481                     when(/\bstatus_file\b/i) {
482                         $g_status_file = $value;
483                     } 
484                     when(/\bpool_conf_template\b/i) {
485                         $g_conf_template = $value;
486                     } 
487                     when(/\bpool_conf_target\b/i) {
488                         $g_conf_target = $value;
489                     } 
490                     when(/\bpool_reload_command\b/i) {
491                         $g_reload_command = $value;
492                     } 
493                     when(/\bpool_mode\b/i) {
494                         $g_mode = lc($value);
495                     } 
496                     when(/\bpool_all_databases\b/i) {
497                         $g_all_databases = checkBoolean($value);
498                     }
499                     when(/\bonly_follow_origins\b/i) {
500                         $g_origins_only = checkBoolean($value);
501                     }
502                     when(/\bmax_ro_lag\b/i) {
503                         $g_max_lag = checkInteger($value);
504                     }
505                 }  
506             }
507         }
508         close (CFGFILE);
509         if (defined($g_user) && (scalar(@g_conninfos) > 0)) {
510            $success = true;
511         }
512         # Replace %mode and %clname here for actual value
513         for ($g_pidfile, $g_logfile, $g_status_file, $g_conf_template, $g_conf_target, $g_reload_command) {
514             s/\%mode/$g_mode/g;
515             s/\%clname/$g_clname/g;
516         }
517
518
519     }
520     else {
521         printLogLn($g_logfile, "ERROR: Could not read configuration from '$infile'");
522     }
523     return $success;
524 }
525
526 sub writePID {
527     my $pidfile = shift;
528     my $success = true;
529
530     eval {
531         open (PIDFILE, ">", $pidfile);
532         print PIDFILE $$;
533         close (PIDFILE);
534         if ($g_debug) {
535             printLogLn($g_logfile, "DEBUG: Created PID file '$pidfile' for process $$");
536         }
537     };
538     if ($@) {
539         printLogLn($g_logfile, "ERROR: unable to write pidfile at '$pidfile' DETAIL $!");       
540         $success = false;
541     }
542     return $success;
543 }
544
545 sub removePID {
546     my $pidfile = shift;
547     my $success = true;
548
549     eval {
550         if (-f $pidfile) {
551             unlink $pidfile;
552             if ($g_debug) {
553                 printLogLn($g_logfile, "DEBUG: Removed PID file '$pidfile'");
554             }
555         }
556         elsif ($g_debug){
557             printLogLn($g_logfile, "DEBUG: PID file '$pidfile' never existed to be removed");
558         } 
559     };
560     if ($@) {
561         printLogLn($g_logfile, "ERROR: unable to remove pidfile at '$pidfile' DETAIL $!");       
562         $success = false;
563     }
564     return $success
565 }
566
567 sub checkBoolean {
568     my $text = shift;
569     my $value = undef;
570     if ( grep /^$text$/i, ("y","yes","t","true","on") ) {
571         $value = true;
572     }
573     elsif ( grep /^$text$/i, ("n","no","f","false","off") ) {
574         $value = false;
575     }
576     return $value;
577 }
578
579 sub checkInteger {
580     my $integer = shift;
581     my $value = undef;
582
583     if (($integer * 1) eq $integer) {
584         $value = int($integer);
585     }
586     return $value;
587 }
588
589 sub checkProvidesAllSets { 
590     my ($originSets, $providerSets) = @_;
591     my %test_hash;
592
593     undef @test_hash{@$originSets};       # add a hash key for each element of @$originSets
594     delete @test_hash{@$providerSets};    # remove all keys for elements of @$providerSets
595
596     return !%test_hash;              # return false if any keys are left in the hash
597 }
598
599 sub isInet {
600     my $address = shift;
601     my $success = true;
602
603     my(@octets) = $address =~ /^(\d{1,3})\.(\d{1,3})\.(\d{1,3})\.(\d{1,3})$/;
604     if (@octets == 4) {
605         foreach (@octets) {
606             unless ($_ <= 255) {
607                 $success = false;
608             }
609         }
610     }
611     else {
612         $success = false;
613     }
614
615     return $success;
616 }
617
618 sub qtrim {
619     my $string = shift;
620     $string =~ s/^('|")+//;
621     $string =~ s/('|")+$//;
622     return $string;
623 }
624
625 sub trim {
626     my $string = shift;
627     $string =~ s/^\s+//;
628     $string =~ s/\s+$//;
629     return $string;
630 }
631
632 sub getRuntime {
633     my ($year, $month, $day, $hour, $min, $sec) = (localtime(time))[5,4,3,2,1,0];
634     my $time = sprintf ("%02d:%02d:%02d on %02d/%02d/%04d", $hour, $min, $sec, $day, $month+1, $year+1900);
635     return $time;
636 }
637
638 sub printLog {
639     my $logfile = shift;
640     my $message = shift;
641
642     print $message;
643
644     if (open(LOGFILE, ">>", $logfile)) {
645         print LOGFILE getRuntime() . " " . $message;
646         close (LOGFILE);
647     }
648     else {
649         printLn("ERROR: Unable to write to logfile $logfile");
650     }
651 }
652
653 sub printLogLn {
654     printLog ($_[0], $_[1] . $/);
655 }
656
657 sub printLn {
658     print ((@_ ? join($/, @_) : $_), $/);
659 }