Add better logging for RPC

This commit is contained in:
Ilia Ross
2026-01-09 18:12:37 +02:00
parent b4a67a0d90
commit 2627ba289e

View File

@@ -78,7 +78,7 @@ if ($use_ipv6) {
} }
$sel = select($rmask, undef, undef, $config_rpc_timeout); $sel = select($rmask, undef, undef, $config_rpc_timeout);
if ($sel <= 0) { if ($sel <= 0) {
print STDERR "fastrpc: accept timed out\n" print STDERR "fastrpc[$$]: accept timed out\n"
if ($gconfig{'rpcdebug'}); if ($gconfig{'rpcdebug'});
exit; exit;
} }
@@ -115,8 +115,15 @@ while(1) {
if ($sel <= 0) { if ($sel <= 0) {
# Don't kill the control session while a tcpwrite/tcpread is # Don't kill the control session while a tcpwrite/tcpread is
# running # running
next if (keys %xfer_kids); my $nk = scalar(keys %xfer_kids);
print STDERR "fastrpc: session timed out\n" if ($nk) {
print STDERR "fastrpc[$$]: idle timeout, but $nk ".
"transfer(s) active: ".
join(",", sort keys %xfer_kids)."\n"
if ($gconfig{'rpcdebug'});
next;
}
print STDERR "fastrpc[$$]: session timed out\n"
if ($gconfig{'rpcdebug'}); if ($gconfig{'rpcdebug'});
last; last;
} }
@@ -132,7 +139,7 @@ while(1) {
exit if ($rv <= 0); exit if ($rv <= 0);
$rawarg .= $got; $rawarg .= $got;
} }
print STDERR "fastrpc: raw $rawarg\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: raw $rawarg\n" if ($gconfig{'rpcdebug'});
my $dumper = substr($rawarg, 0, 5) eq '$VAR1' ? 1 : 0; my $dumper = substr($rawarg, 0, 5) eq '$VAR1' ? 1 : 0;
my $arg = &unserialise_variable($rawarg); my $arg = &unserialise_variable($rawarg);
@@ -140,19 +147,19 @@ while(1) {
my $rv; my $rv;
if ($arg->{'action'} eq 'ping') { if ($arg->{'action'} eq 'ping') {
# Just respond with an OK # Just respond with an OK
print STDERR "fastrpc: ping\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: ping\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 1 }; $rv = { 'status' => 1 };
} }
elsif ($arg->{'action'} eq 'check') { elsif ($arg->{'action'} eq 'check') {
# Check if some module is supported # Check if some module is supported
print STDERR "fastrpc: check $arg->{'module'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: check $arg->{'module'}\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 1, $rv = { 'status' => 1,
'rv' => &foreign_check($arg->{'module'}, undef, undef, 'rv' => &foreign_check($arg->{'module'}, undef, undef,
$arg->{'api'}) }; $arg->{'api'}) };
} }
elsif ($arg->{'action'} eq 'config') { elsif ($arg->{'action'} eq 'config') {
# Get the config for some module # Get the config for some module
print STDERR "fastrpc: config $arg->{'module'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: config $arg->{'module'}\n" if ($gconfig{'rpcdebug'});
my %config = &foreign_config($arg->{'module'}); my %config = &foreign_config($arg->{'module'});
$rv = { 'status' => 1, 'rv' => \%config }; $rv = { 'status' => 1, 'rv' => \%config };
} }
@@ -161,7 +168,7 @@ while(1) {
my $file = $arg->{'file'} ? $arg->{'file'} : my $file = $arg->{'file'} ? $arg->{'file'} :
$arg->{'name'} ? &tempname($arg->{'name'}) : $arg->{'name'} ? &tempname($arg->{'name'}) :
&tempname(); &tempname();
print STDERR "fastrpc: write $file\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: write $file\n" if ($gconfig{'rpcdebug'});
open(FILE, ">$file"); open(FILE, ">$file");
binmode(FILE); binmode(FILE);
print FILE $arg->{'data'}; print FILE $arg->{'data'};
@@ -173,7 +180,7 @@ while(1) {
my $file = $arg->{'file'} ? $arg->{'file'} : my $file = $arg->{'file'} ? $arg->{'file'} :
$arg->{'name'} ? &tempname($arg->{'name'}) : $arg->{'name'} ? &tempname($arg->{'name'}) :
&tempname(); &tempname();
print STDERR "fastrpc: tcpwrite $file\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: tcpwrite $file\n" if ($gconfig{'rpcdebug'});
my $tsock = time().$$; my $tsock = time().$$;
my $tsock6 = $use_ipv6 ? time().$$."v6" : undef; my $tsock6 = $use_ipv6 ? time().$$."v6" : undef;
my $tport = $port + 1; my $tport = $port + 1;
@@ -187,7 +194,7 @@ while(1) {
close(MAIN); close(MAIN);
close(MAIN6) if ($use_ipv6); close(MAIN6) if ($use_ipv6);
# Accept connection in separate process # Accept connection in separate process
print STDERR "fastrpc: tcpwrite $file port $tport\n" print STDERR "fastrpc[$$]: tcpwrite $file port $tport\n"
if ($gconfig{'rpcdebug'}); if ($gconfig{'rpcdebug'});
my $rmask; my $rmask;
vec($rmask, fileno($tsock), 1) = 1; vec($rmask, fileno($tsock), 1) = 1;
@@ -202,12 +209,12 @@ while(1) {
elsif ($use_ipv6 && vec($rmask, fileno($tsock6), 1)) { elsif ($use_ipv6 && vec($rmask, fileno($tsock6), 1)) {
accept(TRANS, $tsock6) || exit; accept(TRANS, $tsock6) || exit;
} }
print STDERR "fastrpc: tcpwrite $file accepted\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: tcpwrite $file accepted\n" if ($gconfig{'rpcdebug'});
my $buf; my $buf;
my $err; my $err;
if (open(FILE, ">$file")) { if (open(FILE, ">$file")) {
binmode(FILE); binmode(FILE);
print STDERR "fastrpc: tcpwrite $file writing\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: tcpwrite $file writing\n" if ($gconfig{'rpcdebug'});
my $bs = &get_buffer_size(); my $bs = &get_buffer_size();
while(read(TRANS, $buf, $bs) > 0) { while(read(TRANS, $buf, $bs) > 0) {
my $ok = (print FILE $buf); my $ok = (print FILE $buf);
@@ -217,10 +224,10 @@ while(1) {
} }
} }
close(FILE); close(FILE);
print STDERR "fastrpc: tcpwrite $file written\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: tcpwrite $file written\n" if ($gconfig{'rpcdebug'});
} }
else { else {
print STDERR "fastrpc: tcpwrite $file open failed $!\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: tcpwrite $file open failed $!\n" if ($gconfig{'rpcdebug'});
$err = "Failed to open $file : $!"; $err = "Failed to open $file : $!";
} }
print TRANS $err ? "$err\n" : "OK\n"; print TRANS $err ? "$err\n" : "OK\n";
@@ -229,7 +236,7 @@ while(1) {
} }
else { else {
$xfer_kids{$cpid} = 1; $xfer_kids{$cpid} = 1;
print STDERR "fastrpc: tcpwrite $file started\n" print STDERR "fastrpc[$$]: tcpwrite $file started\n"
if ($gconfig{'rpcdebug'}); if ($gconfig{'rpcdebug'});
$rv = { 'status' => 1, 'rv' => [ $file, $tport ] }; $rv = { 'status' => 1, 'rv' => [ $file, $tport ] };
} }
@@ -238,7 +245,7 @@ while(1) {
} }
elsif ($arg->{'action'} eq 'read') { elsif ($arg->{'action'} eq 'read') {
# Transfer data from a file # Transfer data from a file
print STDERR "fastrpc: read $arg->{'file'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: read $arg->{'file'}\n" if ($gconfig{'rpcdebug'});
my ($data, $got); my ($data, $got);
open(FILE, "<$arg->{'file'}"); open(FILE, "<$arg->{'file'}");
binmode(FILE); binmode(FILE);
@@ -251,7 +258,7 @@ while(1) {
} }
elsif ($arg->{'action'} eq 'tcpread') { elsif ($arg->{'action'} eq 'tcpread') {
# Transfer data from a file over TCP connection # Transfer data from a file over TCP connection
print STDERR "fastrpc: tcpread $arg->{'file'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: tcpread $arg->{'file'}\n" if ($gconfig{'rpcdebug'});
if (-d $arg->{'file'}) { if (-d $arg->{'file'}) {
$rv = { 'status' => 1, 'rv' => [ undef, "$arg->{'file'} is a directory" ] }; $rv = { 'status' => 1, 'rv' => [ undef, "$arg->{'file'} is a directory" ] };
} }
@@ -296,7 +303,7 @@ while(1) {
} }
else { else {
$xfer_kids{$cpid} = 1; $xfer_kids{$cpid} = 1;
print STDERR "fastrpc: tcpread $arg->{'file'} ". print STDERR "fastrpc[$$]: tcpread $arg->{'file'} ".
"started\n" "started\n"
if ($gconfig{'rpcdebug'}); if ($gconfig{'rpcdebug'});
$rv = { 'status' => 1, $rv = { 'status' => 1,
@@ -309,23 +316,23 @@ while(1) {
} }
elsif ($arg->{'action'} eq 'require') { elsif ($arg->{'action'} eq 'require') {
# require a library # require a library
print STDERR "fastrpc: require $arg->{'module'}/$arg->{'file'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: require $arg->{'module'}/$arg->{'file'}\n" if ($gconfig{'rpcdebug'});
eval { eval {
&foreign_require($arg->{'module'}, &foreign_require($arg->{'module'},
$arg->{'file'}); $arg->{'file'});
}; };
if ($@) { if ($@) {
print STDERR "fastrpc: require error $@\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: require error $@\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 0, 'rv' => $@ }; $rv = { 'status' => 0, 'rv' => $@ };
} }
else { else {
print STDERR "fastrpc: require done\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: require done\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 1 }; $rv = { 'status' => 1 };
} }
} }
elsif ($arg->{'action'} eq 'call') { elsif ($arg->{'action'} eq 'call') {
# execute a function # execute a function
print STDERR "fastrpc: call $arg->{'module'}::$arg->{'func'}(",join(",", @{$arg->{'args'}}),")\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: call $arg->{'module'}::$arg->{'func'}(",join(",", @{$arg->{'args'}}),")\n" if ($gconfig{'rpcdebug'});
my @rv; my @rv;
eval { eval {
local $main::error_must_die = 1; local $main::error_must_die = 1;
@@ -334,7 +341,7 @@ while(1) {
@{$arg->{'args'}}); @{$arg->{'args'}});
}; };
if ($@) { if ($@) {
print STDERR "fastrpc: call error $@\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: call error $@\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 0, 'rv' => $@ }; $rv = { 'status' => 0, 'rv' => $@ };
} }
elsif (@rv == 1) { elsif (@rv == 1) {
@@ -343,11 +350,11 @@ while(1) {
else { else {
$rv = { 'status' => 1, 'arv' => \@rv }; $rv = { 'status' => 1, 'arv' => \@rv };
} }
print STDERR "fastrpc: call $arg->{'module'}::$arg->{'func'} done = ",join(",", @rv),"\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: call $arg->{'module'}::$arg->{'func'} done = ",join(",", @rv),"\n" if ($gconfig{'rpcdebug'});
} }
elsif ($arg->{'action'} eq 'eval') { elsif ($arg->{'action'} eq 'eval') {
# eval some perl code # eval some perl code
print STDERR "fastrpc: eval $arg->{'module'} $arg->{'code'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: eval $arg->{'module'} $arg->{'code'}\n" if ($gconfig{'rpcdebug'});
my $erv; my $erv;
if ($arg->{'module'}) { if ($arg->{'module'}) {
my $pkg = $arg->{'module'}; my $pkg = $arg->{'module'};
@@ -358,7 +365,7 @@ while(1) {
else { else {
$erv = eval $arg->{'code'}; $erv = eval $arg->{'code'};
} }
print STDERR "fastrpc: eval $arg->{'module'} $arg->{'code'} done = $rv error = $@\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: eval $arg->{'module'} $arg->{'code'} done = $rv error = $@\n" if ($gconfig{'rpcdebug'});
if ($@) { if ($@) {
$rv = { 'status' => 0, 'rv' => $@ }; $rv = { 'status' => 0, 'rv' => $@ };
} }
@@ -367,11 +374,11 @@ while(1) {
} }
} }
elsif ($arg->{'action'} eq 'quit') { elsif ($arg->{'action'} eq 'quit') {
print STDERR "fastrpc: quit\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: quit\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 1 }; $rv = { 'status' => 1 };
} }
else { else {
print STDERR "fastrpc: unknown $arg->{'action'}\n" if ($gconfig{'rpcdebug'}); print STDERR "fastrpc[$$]: unknown $arg->{'action'}\n" if ($gconfig{'rpcdebug'});
$rv = { 'status' => 0 }; $rv = { 'status' => 0 };
} }
$rawrv = &serialise_variable($rv, $dumper); $rawrv = &serialise_variable($rv, $dumper);