2 # The RBN connection system
4 # Copyright (c) 2020 Dirk Koopman G1TLH
21 use Math::Round qw(nearest nearest_floor);
23 use Time::HiRes qw(gettimeofday);
70 our $DATA_VERSION = 1;
72 our @ISA = qw(DXChannel);
74 our $startup_delay = 5*60; # don't send anything out until this timer has expired
75 # this is to allow the feed to "warm up" with duplicates
76 # so that the "big rush" doesn't happen.
78 our $minspottime = 30*60; # the time between respots of a callsign - if a call is
79 # still being spotted (on the same freq) and it has been
80 # spotted before, it's spotted again after this time
81 # until the next minspottime has passed.
83 our $beacontime = 5*60; # same as minspottime, but for beacons (and shorter)
85 our $dwelltime = 10; # the amount of time to wait for duplicates before issuing
86 # a spot to the user (no doubt waiting with bated breath).
88 our $filterdef = $Spot::filterdef; # we use the same filter as the Spot system. Can't think why :-).
90 my $spots; # the GLOBAL spot cache
92 my %runtime; # how long each channel has been running
94 our $cachefn = localdata('rbn_cache');
95 our $cache_valid = 4*60; # The cache file is considered valid if it is not more than this old
97 our $maxqrgdiff = 10; # the maximum
98 our $minqual = 2; # the minimum quality we will accept for output
101 my $noinrush = 0; # override the inrushpreventor if set
102 our $maxdeviants = 5; # the number of deviant QRGs to record for skimmer records
110 $spots = {VERSION=>$DATA_VERSION};
112 if (defined $DB::VERSION) {
121 my $self = DXChannel::alloc(@_);
123 # routing, this must go out here to prevent race condx
130 $self->{nouser} = {};
132 $self->{noraw10} = 0;
133 $self->{nospot10} = 0;
134 $self->{nouser10} = {};
135 $self->{norbn10} = 0;
136 $self->{nospothour} = 0;
137 $self->{nouserhour} = {};
138 $self->{norbnhour} = 0;
139 $self->{norawhour} = 0;
141 $self->{lasttime} = $main::systime;
142 $self->{minspottime} = $minspottime;
143 $self->{beacontime} = $beacontime;
144 $self->{showstats} = 0;
145 $self->{pingint} = 0;
146 $self->{nopings} = 0;
154 my ($self, $line, $sort) = @_;
155 my $user = $self->{user};
156 my $call = $self->{call};
157 my $name = $user->{name};
160 my $host = $self->{conn}->peerhost;
162 $self->{hostname} = $host;
164 $self->{name} = $name ? $name : $call;
165 $self->state('prompt'); # a bit of room for further expansion, passwords etc
166 $self->{lang} = $user->lang || $main::lang || 'en';
167 if ($line =~ /host=/) {
168 my ($h) = $line =~ /host=(\d+\.\d+\.\d+\.\d+)/;
169 $line =~ s/\s*host=\d+\.\d+\.\d+\.\d+// if $h;
171 ($h) = $line =~ /host=([\da..fA..F:]+)/;
172 $line =~ s/\s*host=[\da..fA..F:]+// if $h;
176 $self->{hostname} = $h;
179 $self->{width} = 80 unless $self->{width} && $self->{width} > 80;
180 $self->{consort} = $line; # save the connection type
182 LogDbg('DXCommand', "$call connected from $self->{hostname}");
184 # set some necessary flags on the user if they are connecting
185 $self->{registered} = 1;
186 # sort out privilege reduction
191 $nossid =~ s/-\d+$//;
193 $self->{inrbnfilter} = Filter::read_in('rbn', $call, 1)
194 || Filter::read_in('rbn', 'node_default', 1);
196 # clean up qra locators
197 my $qra = $user->qra;
198 $qra = undef if ($qra && !DXBearing::is_qra($qra));
200 my $lat = $user->lat;
201 my $long = $user->long;
202 $user->qra(DXBearing::lltoqra($lat, $long)) if (defined $lat && defined $long);
205 # if we have been running and stopped for a while
206 # if the cache is warm enough don't operate the inrush preventor
207 $self->{inrushpreventor} = exists $runtime{$call} && $runtime{$call} > $startup_delay || $noinrush ? 0 : $main::systime + $startup_delay;
208 dbg("RBN: noinrush: $noinrush, setting inrushpreventor on $self->{call} to $self->{inrushpreventor}");
211 my @queue; # the queue of spots ready to send
218 # my $spots = $self->{spot};
220 # remove leading and trailing spaces
227 my $now = $main::systime;
230 dbg "RBN:RAW,$line" if isdbg('rbnraw');
231 return unless $line=~/^DX\s+de/;
233 my (undef, undef, $origin, $qrg, $call, $mode, $s, $m, $spd, $u, $sort, $t, $tx) = split /[:\s]+/, $line;
235 # fix up FT8 spots from 7001
236 $t = $u, $u = '' if !$t && is_ztime($u);
237 $t = $sort, $sort = '' if !$t && is_ztime($sort);
238 my $qra = $spd, $spd = '' if is_qra($spd);
241 # is this anything like a callsign?
242 unless (is_callsign($call)) {
243 dbg("RBN: ERROR $call from $origin on $qrg is invalid, dumped");
247 $origin =~ s/\-(?:\d{1,2}\-)?\#$//; # get rid of all the crap we aren't interested in
253 dbg qq{RBN:input decode or:$origin qr:$qrg ca:$call mo:$mode s:$s m:$m sp:$spd u:$u sort:$sort t:$t tx:$tx qra:$qra} if isdbg('rbn');
257 ++$self->{norawhour};
263 # fix up times for things like 'NXDXF B' etc
264 if ($tx && is_ztime($t)) {
273 if ($sort && $sort eq 'NCDXF') {
277 if ($sort && $sort eq 'BEACON') {
280 if ($mode =~ /^PSK/) {
283 if ($mode eq 'RTTY') {
287 # The main de-duping key is [call, $frequency], but we probe a bit around that frequency to find a
288 # range of concurrent frequencies that might be in play.
290 # The key to this is deducing the true callsign by "majority voting" (the greater the number of spotters
291 # the more effective this is) together with some lexical analsys probably in conjuction with DXSpider
292 # data sources (for singleton spots) to then generate a "centre" from and to zone (whatever that will mean if it isn't the usual one)
293 # and some heuristical "Kwalitee" rating given distance from the zone centres of spotter, recipient user
294 # and spotted. A map can be generated once per user and spotter as they are essentially mostly static.
295 # The spotted will only get a coarse position unless other info is available. Programs that parse
296 # DX bulletins and the online data online databases could be be used and then cached.
298 # Obviously users have to opt in to receiving RBN spots and other users will simply be passed over and
301 # Clearly this will only work in the 'mojo' branch of DXSpider where it is possible to pass off external
302 # data requests to ephemeral or semi resident forked processes that do any grunt work and the main
303 # process to just the standard "message passing" which has been shown to be able to sustain over 5000
304 # per second (limited by the test program's output and network speed, rather than DXSpider's handling).
307 my $nqrg = nearest(1, $qrg * 10); # normalised to nearest Khz
308 my $sp = "$call|$nqrg"; # hopefully the skimmers will be calibrated at least this well!
311 my $cand = $spots->{$sp};
314 for ($i = $nqrg; !$cand && $i <= $nqrg+$search; $i += 1) {
316 $cand = $spots->{$new}, last if exists $spots->{$new};
319 my $diff = $i - $nqrg;
320 dbg(qq{RBN: QRG Diff using $new (+$diff) for $sp for qrg $qrg}) if (isdbg('rbnqrg') || isdbg('rbn'));
326 for ($i = $nqrg; !$cand && $i >= $nqrg-$search; $i -= 1) {
328 $cand = $spots->{$new}, last if exists $spots->{$new};
331 my $diff = $nqrg - $i;
332 dbg(qq{RBN: QRG Diff using $new (-$diff) for $sp for qrg $qrg}) if (isdbg('rbnqrg') || isdbg('rbn'));
337 # if we have one and there is only one slot and that slot's time isn't expired for respot then return
339 if ($cand && ref $cand) {
340 if (@$cand <= CData) {
341 unless ($self->{minspottime} > 0 && $now - $cand->[CTime] >= $self->{minspottime}) {
342 dbg("RBN: key: '$sp' call: $call qrg: $qrg DUPE \@ ". atime(int $cand->[CTime])) if isdbg('rbn');
346 dbg("RBN: key: '$sp' RESPOTTING call: $call qrg: $qrg last seen \@ ". atime(int $cand->[CTime])) if isdbg('rbn');
347 $cand->[CTime] = $now;
351 # otherwise we have a spot being built up at the moment
353 dbg("RBN: key '$sp' = '$cand' not ref");
357 # here we either have an existing spot record buildup on the go, or we need to create the first one
359 $spots->{$sp} = $cand = [$now, 0];
360 dbg("RBN: key: '$sp' call: $call qrg: $qrg NEW" . ($respot ? ' RESPOT' : '')) if isdbg('rbn');
363 # add me to the display queue unless we are waiting for initial in rush to finish
364 return unless $noinrush || $self->{inrushpreventor} < $main::systime;
366 # build up a new record and store it in the buildup
367 # deal with the unix time
368 my ($hh,$mm) = $t =~ /(\d\d)(\d\d)Z$/;
369 my $utz = $hh*3600 + $mm*60 + $main::systime_daystart; # possible issue with late spot from previous day
370 $utz -= 86400 if $utz > $now+3600; # too far ahead, drag it back one day
372 # create record and add into the buildup
373 my $r = [$origin, nearest(.1, $qrg), $call, $mode, $s, $t, $utz, $respot, $u];
374 my @s = Spot::prepare($r->[RQrg], $r->[RCall], $r->[RUtz], '', $r->[ROrigin]);
376 dbg("RBN: ERROR invalid prefix/callsign $call from $origin-# on $qrg, dumped");
380 if ($self->{inrbnfilter}) {
381 my ($want, undef) = $self->{inrbnfilter}->it($s);
384 $r->[RSpotData] = \@s;
386 ++$self->{queue}->{$sp};# unless @$cand>= CData; # queue the KEY (not the record)
388 dbg("RBN: key: '$sp' ADD RECORD call: $call qrg: $qrg origin: $origin") if isdbg('rbn');
393 dbg "RBN:DATA,$line" if isdbg('rbn');
397 # we should get the spot record minus the time, so just an array of record (arrays)
406 ++$self->{norbnhour};
408 # $r = [$origin, $qrg, $call, $mode, $s, $utz, $respot];
410 my $mode = $cand->[CData]->[RMode]; # as all the modes will be the same;
412 my @dxchan = DXChannel::get_all();
414 foreach my $dxchan (@dxchan) {
415 next unless $dxchan->is_user;
416 my $user = $dxchan->{user};
417 next unless $user && $user->wantrbn;
419 # does this user want this sort of spot at all?
421 ++$want if $user->wantbeacon && $mode =~ /^BCN|DXF/;
422 ++$want if $user->wantcw && $mode =~ /^CW/;
423 ++$want if $user->wantrtty && $mode =~ /^RTT/;
424 ++$want if $user->wantpsk && $mode =~ /^PSK|FSK|MSK/;
425 ++$want if $user->wantft && $mode =~ /^FT/;
427 dbg(sprintf("RBN: spot selection for $dxchan->{call} mode: '$mode' want: $want flags rbn:%d ft:%d bcn:%d cw:%d psk:%d rtty:%d",
434 )) if isdbg('rbnll');
436 # send one spot to one user out of the ones that we have
437 $self->dx_spot($dxchan, $quality, $cand) if $want;
447 my $call = $dxchan->{call};
448 my $strength = 100; # because it could if we talk about FTx
454 ++$self->{nousers}->{$call};
455 ++$self->{nousers10}->{$call};
456 ++$self->{nousershour}->{$call};
459 my $rf = $dxchan->{rbnfilter} || $dxchan->{spotsfilter};
462 foreach my $r (@$cand) {
463 # $r = [$origin, $qrg, $call, $mode, $s, $t, $utz, $respot, $qra];
464 # Spot::prepare($qrg, $call, $utz, $comment, $origin);
465 next unless $r && ref $r;
467 $qra = $r->[RQra] if !$qra && $r->[RQra] && is_qra($r->[RQra]);
469 $comment = sprintf "%-3s %2ddB $quality", $r->[RMode], $r->[RStrength];
470 my $s = $r->[RSpotData]; # the prepared spot
471 $s->[SComment] = $comment; # apply new generated comment
473 ++$zone{$s->[SZone]}; # save the spotter's zone
475 # save the lowest strength one
476 if ($r->[RStrength] < $strength) {
477 $strength = $r->[RStrength];
479 dbg("RBN: STRENGTH spot: $s->[SCall] qrg: $s->[SQrg] origin: $s->[SOrigin] dB: $r->[RStrength] < $strength") if isdbg 'rbnll';
483 my ($want, undef) = $rf->it($s);
484 dbg("RBN: FILTERING for $call spot: $s->[SCall] qrg: $s->[SQrg] origin: $s->[SOrigin] dB: $r->[RStrength] com: '$s->[SComment]' want: " . ($want ? 'YES':'NO')) if isdbg 'rbnll';
492 $saver = $filtered; # if nothing passed the filter's lips then $saver == $filtered == undef !
497 # create a zone list of spotters
498 delete $zone{$saver->[SZone]}; # remove this spotter's zone (leaving all the other zones)
499 my $z = join ',', sort {$a <=> $b} keys %zone;
501 # alter spot data accordingly
502 $saver->[SComment] .= " Z:$z" if $z;
504 dbg("RBN: SENDING to $call spot: $saver->[SCall] qrg: $saver->[SQrg] origin: $saver->[SOrigin] $saver->[SComment]") if isdbg 'rbnll';
505 if ($dxchan->{ve7cc}) {
506 my $call = $saver->[SOrigin];
507 $saver->[SOrigin] .= '-#';
508 $buf = VE7CC::dx_spot($dxchan, @$saver);
509 $saver->[SOrigin] = $call;
511 my $call = $saver->[SOrigin];
512 $saver->[SOrigin] = substr($call, 0, 6);
513 $saver->[SOrigin] .= '-#';
514 $buf = $dxchan->format_dx_spot(@$saver);
515 $saver->[SOrigin] = $call;
518 $dxchan->local_send('N', $buf);
522 ++$self->{nospothour};
525 my $user = DXUser::get_current($saver->[SCall]) || DXUser->new($saver->[SCall]);
526 unless ($user->qra && is_qra($user->qra)) {
528 dbg("RBN: update qra on $saver->[SCall] to $qra");
538 foreach my $dxchan (DXChannel::get_all()) {
539 next unless $dxchan->is_rbn;
541 # At this point we run the queue to see if anything can be sent onwards to the punter
542 my $now = $main::systime;
543 my $ta = [gettimeofday];
546 # now run the waiting queue which just contains KEYS ($call|$qrg)
547 foreach my $sp (keys %{$dxchan->{queue}}) {
548 my $cand = $spots->{$sp};
550 unless ($cand && $cand->[CTime]) {
551 dbg "RBN Cand $sp " . ($cand ? 'def' : 'undef') . " [CTime] " . ($cand->[CTime] ? 'def' : 'undef') . " dwell $dwelltime";
554 if ($now >= $cand->[CTime] + $dwelltime ) {
555 # we have a candidate, create qualitee value(s);
556 unless (@$cand > CData) {
557 dbg "RBN: QUEUE key '$sp' MISSING RECORDS, IGNORED" . dd($cand) if isdbg 'rbnqueue';
560 dbg "RBN: QUEUE PROCESSING key: '$sp' $now >= $cand->[CTime]" if isdbg 'rbnqueue';
561 my $quality = @$cand - CData;
562 my $spotters = $quality;
564 # dump it and remove it from the queue if it is of unadequate quality
565 if ($quality < $minqual) {
566 if (isdbg('rbnskim')) {
567 my $r = $cand->[CData];
569 my $s = "RBN: SPOT IGNORED(Q:$quality < Q:$minqual) key: '$sp' = $r->[RCall] on $r->[RQrg] by $r->[ROrigin] \@ $r->[RTime] route: $dxchan->{call}";
573 delete $spots->{$sp}; # don't remember it either - this means that a spot HAS to come in with sufficient spotters to be processed.
574 delete $dxchan->{queue}->{$sp};
578 $quality = 9 if $quality > 9;
579 $cand->[CQual] = $quality if $quality > $cand->[CQual];
587 foreach $r (@$cand) {
589 if (exists $seen{$r->[ROrigin]}) {
593 $seen{$r->[ROrigin]} = 1;
594 $band ||= int $r->[RQrg] / 1000;
595 $sk = "SKIM|$r->[ROrigin]|$band";
596 $skimmer = $spots->{$sk};
598 $skimmer = $spots->{$sk} = [0+0, 0+0, 0+0, $now, []]; # this stupid incantation is to make sure than there are no JSON nulls!
599 dbg("RBN:SKIM new slot $sk " . $json->encode($skimmer)) if isdbg('rbnskim');
601 $qrg{$r->[RQrg]} += ($skimmer->[DScore] || 1);
604 # determine the most likely qrg and then set it
609 while (my ($k, $votes) = each %qrg) {
610 $qrg = $k, $mv = $votes if $votes >= $mv;
613 # spit out the deviants
614 foreach $r (@$cand) {
615 next unless $r && ref $r;
616 my $diff = $c > 1 ? nearest(.1, $r->[RQrg] - $qrg) : 0;
617 $sk = "SKIM|$r->[ROrigin]|$band";
618 $skimmer = $spots->{$sk};
619 $skimmer->[DBad] ||= 0+0; # stop JSON nulls?
620 $skimmer->[DEviants] ||= []; # ditto
622 ++$skimmer->[DBad] if $skimmer->[DBad] < $maxdeviants;
623 --$skimmer->[DGood] if $skimmer->[DGood] > 0;
624 push @deviant, sprintf("$r->[ROrigin]:%+.1f", $diff);
625 push @{$skimmer->[DEviants]}, $diff;
626 shift @{$skimmer->[DEviants]} while @{$skimmer->[DEviants]} > $maxdeviants;
628 ++$skimmer->[DGood] if $skimmer->[DGood] < $maxdeviants;
629 --$skimmer->[DBad] if $skimmer->[DBad] > 0;
630 shift @{$skimmer->[DEviants]};
632 $skimmer->[DScore] = $skimmer->[DGood] - $skimmer->[DBad];
633 $skimmer->[DScore] ||= 0.2; # minimun score
634 dbg("RBN:SKIM key $sp slot $sk $r->[RQrg] - $qrg = $diff " . $json->encode($skimmer)) if isdbg('rbnskim');
635 $skimmer->[DLastin] = $now;
636 $r->[RSpotData]->[SQrg] = $qrg if $qrg && $c > 1; # set all the QRGs to the agreed value
639 $qrg = (sprintf "%.1f", $qrg)+0;
642 my $squality = "Q:$cand->[CQual]";
643 $squality .= '*' if $c > 1;
644 $squality .= '+' if $r->[Respot];
646 if (isdbg('progress')) {
647 my $s = "RBN: SPOT key: '$sp' = $r->[RCall] on $r->[RQrg] by $r->[ROrigin] \@ $r->[RTime] $squality route: $dxchan->{call}";
649 $s .= " QRGScore $mv Deviants ($td/$spotters): ";
650 $s .= join(', ', sort @deviant) if $td;
654 # finally send it out to any waiting public
655 send_dx_spot($dxchan, $squality, $cand);
657 # clear out the data and make this now just "spotted", but no further action required until respot time
658 dbg "RBN: QUEUE key '$sp' cleared" if isdbg 'rbn';
660 delete $spots->{$sp};
661 delete $dxchan->{queue}->{$sp};
663 # calculate new sp (which will be 70% likely the same as the old one)
664 # we do this to cope with the fact that the first spotter may well be "wrongly calibrated" giving a qrg that disagrees with the majority.
665 # and we want to store the key that corresponds to majority opinion.
666 my $nqrg = nearest(1, $qrg * 10); # normalised to nearest Khz
667 my $nsp = "$r->[RCall]|$nqrg";
669 dbg("RBN:SKIM CHANGE KEY sp '$sp' -> '$nsp' for storage") if isdbg('rbnskim');
670 $spots->{$nsp} = [$now, $cand->[CQual]];
674 dbg sprintf("RBN: QUEUE key: '$sp' SEND time not yet reached %.1f secs left", $cand->[CTime] + $dwelltime - $now) if isdbg 'rbnqueue';
677 if (isdbg('rbntimer')) {
678 my $diff = _diffus($ta);
679 dbg "RBN: TIMER process queue for call: $dxchan->{call} $items spots $diff uS";
686 foreach my $dxchan (DXChannel::get_all()) {
687 next unless $dxchan->is_rbn;
688 dbg "RBN:STATS minute $dxchan->{call} raw: $dxchan->{noraw} retrieved spots: $dxchan->{norbn} delivered: $dxchan->{nospot} after filtering to users: " . scalar keys %{$dxchan->{nousers}} if isdbg('rbnstats');
689 if ($dxchan->{noraw} == 0 && $dxchan->{lasttime} > 60) {
690 LogDbg('RBN', "RBN: no input from $dxchan->{call}, disconnecting");
693 $dxchan->{noraw} = $dxchan->{norbn} = $dxchan->{nospot} = 0; $dxchan->{nousers} = {};
694 $runtime{$dxchan->{call}} += 60;
697 # save the spot cache
698 write_cache() unless $main::systime + $startup_delay < $main::systime;;
705 while (my ($k,$cand) = each %{$spots}) {
706 next if $k eq 'VERSION';
707 next if $k =~ /^O\|/;
708 next if $k =~ /^SKIM\|/;
710 if ($main::systime - $cand->[CTime] > $minspottime*2) {
718 dbg "RBN:STATS spot cache remain: $count removed: $removed"; # if isdbg('rbn');
719 foreach my $dxchan (DXChannel::get_all()) {
720 next unless $dxchan->is_rbn;
721 my $nq = keys %{$dxchan->{queue}};
722 my $pc = $dxchan->{noraw10} ? sprintf("%.1f%%",$dxchan->{norbn10}*100/$dxchan->{noraw10}) : '0.0%';
723 dbg "RBN:STATS 10-minute $dxchan->{call} queue: $nq raw: $dxchan->{noraw10} retrieved spots: $dxchan->{norbn10} ($pc) delivered: $dxchan->{nospot10} after filtering to users: " . scalar keys %{$dxchan->{nousers10}};
724 $dxchan->{noraw10} = $dxchan->{norbn10} = $dxchan->{nospot10} = 0; $dxchan->{nousers10} = {};
730 foreach my $dxchan (DXChannel::get_all()) {
731 next unless $dxchan->is_rbn;
732 my $nq = keys %{$dxchan->{queue}};
733 my $pc = $dxchan->{norawhour} ? sprintf("%.1f%%",$dxchan->{norbnhour}*100/$dxchan->{norawhour}) : '0.0%';
734 dbg "RBN:STATS hour $dxchan->{call} queue: $nq raw: $dxchan->{norawhour} retrieved spots: $dxchan->{norbnhour} ($pc) delivered: $dxchan->{nospothour} after filtering to users: " . scalar keys %{$dxchan->{nousershour}};
735 $dxchan->{norawhour} = $dxchan->{norbnhour} = $dxchan->{nospothour} = 0; $dxchan->{nousershour} = {};
746 my $ta = [ gettimeofday ];
748 my $s = eval {$json->encode($spots)};
750 my $fh = IO::File->new(">$cachefn") or confess("writing $cachefn $!");
754 dbg("RBN:Write_cache error '$@'");
757 my $diff = _diffms($ta);
758 dbg("RBN:WRITE_CACHE time to write: $diff mS");
764 my $mt = (stat($cachefn))[9];
765 my $t = $main::systime - $mt || 1;
766 my $p = difft($mt, 2);
767 if ($t < $cache_valid) {
768 dbg("RBN:check_cache '$cachefn' spot cache exists, created $p ago and not too old");
769 my $fh = IO::File->new($cachefn);
774 dbg("RBN:check_cache cache read size " . length $s);
777 dbg("RBN:check_cache file read error $!");
781 eval {$spots = $json->decode($s)};
782 if ($spots && ref $spots) {
783 if (exists $spots->{VERSION} && $spots->{VERSION} == $DATA_VERSION) {
784 # now clean out anything that is current
785 while (my ($k, $cand) = each %$spots) {
786 next if $k eq 'VERSION';
787 next if $k =~ /^O\|/;
788 next if $k =~ /^SKIM\|/;
789 if (@$cand > CData) {
790 $spots->{$k} = [$cand->[CTime], $cand->[CQual]];
793 dbg("RBN:check_cache spot cache restored");
797 dbg("RBN::checkcache error decoding $@");
800 my $d = difft($main::systime-$cache_valid);
801 dbg("RBN::checkcache '$cachefn' created $p ago is too old (> $d), ignored");
804 dbg("RBN:check_cache '$cachefn' spot cache not present");