From: Dirk Koopman <djk@tobit.co.uk>
Date: Sun, 19 Apr 2020 15:12:57 +0000 (+0100)
Subject: improve spawn dbg, move "use Mojolicious"
X-Git-Url: http://dxcluster.org/gitweb/gitweb.cgi?a=commitdiff_plain;h=ed993b76a84e36b22efd1fc762d6a466497bcf7e;p=spider.git

improve spawn dbg, move "use Mojolicious"

We have moved the first use of "use Mojolicious <version>" AFTER the
"use DXDebug" to allow capture of Mojo errors into the debug log.
---

diff --git a/perl/DXCommandmode.pm b/perl/DXCommandmode.pm
index d5271313..3d5ce0c9 100644
--- a/perl/DXCommandmode.pm
+++ b/perl/DXCommandmode.pm
@@ -1265,22 +1265,6 @@ sub send_motd
 	$self->send_file($motd) if -e $motd;
 }
 
-sub _diffms
-{
-	return unless isdbg('chan');
-	my $call = shift;
-	my $line = shift;
-	my $ta = shift;
-	my $tb = shift || [gettimeofday];
-
-	my $a = int($ta->[0] * 1000) + int($ta->[1] / 1000); 
-	my $b = int($tb->[0] * 1000) + int($tb->[1] / 1000);
-	my $msecs = $b - $a;
-
-	my $s = "forkcall stats: $call '$line' ";
-	$s .= "${msecs}mS";
-	dbg($s);
-}
 
 # Punt off a long running command into a separate process
 #
@@ -1324,6 +1308,7 @@ sub spawn_cmd
 					 $s .= ", args: " . join(', ', @$args) if $args && @$args;
 				 }
 				 my @res = $cmdref->(@$args);
+#				 diffms("rcmd from $call 1", $line, $t0, scalar @res) if isdbg('chan');
 				 return @res;
 			 },
 #			 $args,
@@ -1333,7 +1318,7 @@ sub spawn_cmd
 				 return unless $dxchan;
 
 				 if ($err) {
-					 my $s = "DXCommand::spawn_cmd: call $call error $err";
+					 my $s = "DXProt::spawn_cmd: call $call error $err";
 					 dbg($s) if isdbg('chan');
 					 $dxchan->send($s);
 					 return;
@@ -1349,7 +1334,7 @@ sub spawn_cmd
 						 $dxchan->send(@res);
 					 }
 				 }
-				 _diffms($call, $line, $t0);
+				 diffms("by $call", $line, $t0, scalar @res) if isdbg('chan');
 			 });
 	
 	return @out;
diff --git a/perl/DXCron.pm b/perl/DXCron.pm
index c011d7b3..9a3aac50 100644
--- a/perl/DXCron.pm
+++ b/perl/DXCron.pm
@@ -14,7 +14,7 @@ use DXM;
 use DXDebug;
 use IO::File;
 use DXLog;
-
+use Time::HiRes qw(gettimeofday tv_interval);
 use Mojo::IOLoop::Subprocess;
 
 use strict;
@@ -245,11 +245,16 @@ sub start_connect
 sub spawn
 {
 	my $line = shift;
+	my $t0 = [gettimeofday];
 
 	dbg("DXCron::spawn: $line") if isdbg("cron");
 	my $fc = Mojo::IOLoop::Subprocess->new();
 	$fc->run(
-			 sub {my @res = `$line`; return @res},
+			 sub {
+				 my @res = `$line`;
+#				 diffms("DXCron spawn 1", $line, $t0, scalar @res) if isdbg('chan');
+				 return @res
+			 },
 			 sub {
 				 my ($fc, $err, @res) = @_; 
 				 if ($err) {
@@ -261,6 +266,7 @@ sub spawn
 					 chomp;
 					 dbg("DXCron::spawn: $_") if isdbg("cron");
 				 }
+				 diffms("by DXCron::spawn", $line, $t0, scalar @res) if isdbg('chan');
 			 }
 			);
 }
@@ -268,6 +274,7 @@ sub spawn
 sub spawn_cmd
 {
 	my $line = shift;
+	my $t0 = [gettimeofday];
 
 	dbg("DXCron::spawn_cmd run: $line") if isdbg('cron');
 	my $fc = Mojo::IOLoop::Subprocess->new();
@@ -276,6 +283,7 @@ sub spawn_cmd
 				 $main::me->{_nospawn} = 1;
 				 my @res = $main::me->run_cmd($line);
 				 delete $main::me->{_nospawn};
+#				 diffms("DXCron spawn_cmd 1", $line, $t0, scalar @res) if isdbg('chan');
 				 return @res;
 			 },
 			 sub {
@@ -288,6 +296,7 @@ sub spawn_cmd
 					 chomp;
 					 dbg("DXCron::spawn_cmd: $_") if isdbg("cron");
 				 }
+				 diffms("by DXCron::spawn_cmd", $line, $t0, scalar @res) if isdbg('chan');
 			 }
 			);
 }
diff --git a/perl/DXProt.pm b/perl/DXProt.pm
index 9493637a..d7e34e61 100644
--- a/perl/DXProt.pm
+++ b/perl/DXProt.pm
@@ -1231,6 +1231,7 @@ sub spawn_cmd
 				 }
 
 				 my @res = $cmdref->(@$args);
+#				 diffms("by $call 1", $line, $t0, scalar @res) if isdbg('chan');
 				 return @res;
 			 },
 #			 $args,
@@ -1260,7 +1261,7 @@ sub spawn_cmd
 						 $self->send(@res);
 					 }
 				 }
-				 DXCommandmode::_diffms($call, $line, $t0);
+				 diffms("rcmd from $user on $call", $line, $t0, scalar @res) if isdbg('chan');
 			 });
 	
 	return @out;
diff --git a/perl/DXUtil.pm b/perl/DXUtil.pm
index b9afba12..157ff609 100644
--- a/perl/DXUtil.pm
+++ b/perl/DXUtil.pm
@@ -13,7 +13,7 @@ use Date::Parse;
 use IO::File;
 use File::Copy;
 use Data::Dumper;
-
+use Time::HiRes qw(gettimeofday tv_interval);
 
 use strict;
 
@@ -27,6 +27,7 @@ require Exporter;
              print_all_fields cltounix unpad is_callsign is_latlong
 			 is_qra is_freq is_digits is_pctext is_pcflag insertitem deleteitem
 			 is_prefix dd is_ipaddr $pi $d2r $r2d localdata localdata_mv
+			 diffms
             );
 
 
@@ -497,3 +498,21 @@ sub localdata_mv
 	}
 }
 
+# measure the time taken for something to happen; use Time::HiRes qw(gettimeofday tv_interval);
+sub diffms
+{
+	my $call = shift;
+	my $line = shift;
+	my $ta = shift;
+	my $no = shift;
+	my $tb = shift || [gettimeofday];
+
+	my $a = int($ta->[0] * 1000) + int($ta->[1] / 1000); 
+	my $b = int($tb->[0] * 1000) + int($tb->[1] / 1000);
+	my $msecs = $b - $a;
+
+	$line =~ s|\s+$||;
+	my $s = "subprocess stats cmd: '$line' $call ${msecs}mS";
+	$s .= " $no lines" if $no;
+	DXDebug::dbg($s);
+}
diff --git a/perl/cluster.pl b/perl/cluster.pl
index 9e14396b..6dc3573a 100755
--- a/perl/cluster.pl
+++ b/perl/cluster.pl
@@ -89,11 +89,12 @@ use SysVar;
 
 use strict;
 
-use Mojolicious 7.26;
+# order here is important - DXDebug snarfs Carp et al so that Mojo errors go into the debug log
+use DXDebug;
 
+use Mojolicious 7.26;
 use Mojo::IOLoop;
 
-use DXDebug;
 use Msg;
 use IntMsg;
 use Internet;
@@ -146,6 +147,8 @@ use DXSql;
 use IsoTime;
 use BPQMsg;
 
+
+
 use Data::Dumper;
 use IO::File;
 use Fcntl ':flock';