Index: openacs-4/packages/boomerang/tcl/boomerang-procs.tcl =================================================================== RCS file: /usr/local/cvsroot/openacs-4/packages/boomerang/tcl/boomerang-procs.tcl,v diff -u -r1.13 -r1.14 --- openacs-4/packages/boomerang/tcl/boomerang-procs.tcl 30 Apr 2018 09:01:14 -0000 1.13 +++ openacs-4/packages/boomerang/tcl/boomerang-procs.tcl 3 Sep 2024 15:37:35 -0000 1.14 @@ -15,26 +15,23 @@ @author Gustaf Neumann @creation-date 2 Jan 2018 - @cvs-id $Id$ } namespace eval ::boomerang { - - set package_id [apm_package_id_from_key "boomerang"] - + variable parameter_info # # It is possible to configure the version of the boomerang # plugin also via NaviServer config file: # # ns_section ns/server/${server}/acs/boomerang - # ns_param version 1.0.1514200883 + # ns_param version 1.737.0 # + set parameter_info { + package_key boomerang + parameter_name BootstrapVersion + default_value 1.737.0 + } - set version [parameter::get \ - -package_id $package_id \ - -parameter Version \ - -default 1.0.1514200883] - # # Boomerang response handler # @@ -84,7 +81,7 @@ set :json_map($orig) $new } - :object method ms_to_utc {ms} { + :object method ms_to_utc {ms:integer} { set seconds [expr {$ms / 1000}] set fraction [format %03d [expr {$ms - ($seconds * 1000)}]] return [clock format $seconds -format "%Y-%m-%dT%H:%M:%S" -gmt 1].${fraction}Z @@ -134,75 +131,167 @@ return "{[join $result ,]}" } + :object method latest_value {entries field} { + # + # When client comes to a premature end, take + # the latest time. Note that some values below + # might become negative in such situations, + # but this is handled via sanity checks. + # + set l $entries + set l1 [lsort -integer -stride 2 -index 1 [concat {*}[lmap {key value} $l { + if {![string is entier -strict $value]} continue + list $key $value + }]]] + set latest_value [lindex $l1 end] + ns_log warning "boomerang: set missing '$field' to latest value from " \ + [lindex $l1 end-1] $latest_value \n\ + $l1 + return $latest_value + } + :public object method record {-ns_set:required -peeraddr:required} { set t0 [clock clicks -microseconds] #xotcl::Object log "boomerang::record start" set entries [ns_set array $ns_set] if {[ns_set size $ns_set] < 1 || ![dict exists $entries u]} { - ns_log notice "boomerang: no (valid) measurement variablables are provided" + ns_log notice "boomerang: no (valid) measurement variables are provided" return - } + } # - # We have a non-empty ns_set, that will not cause an - # exception below. Add aslwasys the peer address to the + # We have a nonempty ns_set, that will not cause an + # exception below. Add always the peer address to the # result dict. # dict set entries clientip $peeraddr - if {![dict exists $entries rt.tstart]} { + if {![dict exists $entries rt.tstart] && [dict exists $entries nt_nav_st]} { + dict set entries rt.tstart [dict get $entries nt_nav_st] + } + + if {[dict exists $entries err]} { + ad_log warning "boomerang: returned error: [dict get $entries err]\n\ + Request-info:\n[util::request_info -with_headers]" + set record 0 + } elseif {![dict exists $entries rt.tstart]} { ns_log notice "boomerang: no rt.tstart value in $entries" set record 0 + } elseif {![string is entier -strict [dict get $entries rt.tstart]]} { + ns_log notice "boomerang: rt.tstart is not a valid timestamp <[dict get $entries rt.tstart]>" + set record 0 } else { dict set entries @timestamp [:ms_to_utc [dict get $entries rt.tstart]] - # # Do we have W3C "Navigation Timing" information? # Just record data containing this information. # - # Other entries have often strange t_done values: e.g. a - # reload of a page, having an automatic refresh after many - # refreshes will cause such a beacon GET request with a - # t_done time span reaching to the original load of the - # page. + # Other entries have often strange t_done values: + # e.g., a reload of a page, having an automatic + # refresh after many refreshes will cause such a + # beacon GET request with a t_done time span reaching + # to the original load of the page. # - if {[dict exists $entries nt_con_st]} { + # Examples: + # `nt_nav_st`: `performance.timing.navigationStart` + # `nt_con_st`: `performance.timing.connectStart` + # `nt_con_end`: `performance.timing.connectEnd` + # `nt_req_st`: `performance.timing.requestStart` + # `nt_load_end`:`performance.timing.loadEventEnd` + + if {[dict exists $entries nt_req_st] && [dict exists $entries nt_nav_st]} { # # Add nt_*_time variables according to the "Navigation Timing" W3C recommendation # up to domComplete (see https://www.w3.org/TR/navigation-timing/#processing-model) # dict set entries nt_start_time [expr {[dict get $entries nt_req_st] - [dict get $entries nt_nav_st]}] - dict set entries nt_tcp_time [expr {[dict get $entries nt_con_end] - [dict get $entries nt_con_st]}] - dict set entries nt_request_time [expr {[dict get $entries nt_res_st] - [dict get $entries nt_req_st]}] - dict set entries nt_response_time [expr {[dict get $entries nt_res_end] - [dict get $entries nt_res_st]}] - dict set entries nt_processing_time [expr {[dict get $entries nt_domcomp] - [dict get $entries nt_res_end]}] - dict set entries nt_total_time [expr {[dict get $entries nt_load_end] - [dict get $entries nt_nav_st]}] - # - # Sanity checks for the computed fields: - # - no *_time can be larger than t_done - # - no *_time must be negative - # - check for unrealistic high t_done times (caused be technicalities) - set t_done [dict get $entries t_done] - set time_fields { - nt_start_time nt_tcp_time nt_request_time nt_response_time - nt_processing_time nt_total_time + if {![dict exists $entries nt_con_st]} { + # + # Sometimes, nt_con_st and nt_con_end are + # missing. In such cases, we have probably an + # already established connection. Therefore, + # set nt_tcp_time to 0. + dict set entries nt_tcp_time 0 + } else { + dict set entries nt_tcp_time \ + [expr {[dict get $entries nt_con_end] - [dict get $entries nt_con_st]}] } - foreach time_field $time_fields { - set v [dict get $entries $time_field] - if {$v < 0 || $v > $t_done} { - ns_log Warning "boomerang: strange value for $time_field: <$v> computed from $entries" - dict set entries $time_field 0 + + dict set entries nt_request_time \ + [expr {[dict get $entries nt_res_st] - [dict get $entries nt_req_st]}] + + # + # Sometimes, when requests are interrupted, the *end + # time is missing, although the *start time is + # available. + # + foreach field {nt_res_end nt_load_end} { + if {![dict exists $entries $field]} { + dict set entries $field [:latest_value $entries $field] } } - if {[dict get $entries nt_total_time] + 500 < $t_done} { - ns_log Warning "boomerang: nt_total_time [dict get $entries nt_total_time] < t_done $t_done" + dict set entries nt_response_time \ + [expr {[dict get $entries nt_res_end] - [dict get $entries nt_res_st]}] + + if {![dict exists $entries t_done]} { + dict set entries t_done \ + [expr {[dict get $entries nt_load_end] - [dict get $entries nt_nav_st]}] } - set record 1 + + if {![dict exists $entries nt_domcomp]} { + dict set entries nt_processing_time 0 + } else { + set timediff [expr {[dict get $entries nt_domcomp] - [dict get $entries nt_res_end]}] + dict set entries nt_processing_time \ + [expr {[dict get $entries nt_domcomp] - [dict get $entries nt_res_end]}] + } + + if {[dict exists $entries nt_load_end]} { + dict set entries nt_total_time \ + [expr {[dict get $entries nt_load_end] - [dict get $entries nt_nav_st]}] + } elseif {[dict exists $entries t_done]} { + dict set entries nt_total_time [dict get $entries t_done] + } elseif {[dict exists $entries rt.end]} { + dict set entries nt_total_time \ + [expr {[dict get $entries rt.end] - [dict get $entries nt_nav_st]}] + dict set entries t_done [dict get $entries nt_total_time] + } else { + ns_log error "boomerang: cannot determine nt_total_time (no load_end, t_done, rt.end)\nentries: $entries" + error "cannot determine nt_total_time" + } + + if {[dict exists $entries t_done]} { + # + # Sanity checks for the computed fields: + # - no *_time can be larger than t_done + # - no *_time must be negative + # - check for unrealistic high t_done times (caused be technicalities) + set t_done [dict get $entries t_done] + set max_time [expr {$t_done + 1}] + set time_fields { + nt_start_time nt_tcp_time nt_request_time nt_response_time + nt_processing_time nt_total_time + } + foreach time_field $time_fields { + set v [dict get $entries $time_field] + if {$v < 0 || $v > $max_time} { + ns_log warning "boomerang: strange value for $time_field: <$v> computed from $entries" + dict set entries $time_field 0 + } + } + if {[dict get $entries nt_total_time] + 500 < $t_done} { + ns_log warning "boomerang: nt_total_time [dict get $entries nt_total_time] < t_done $t_done" + } + set record 1 + } else { + ns_log warning "boomerang: no value for 't_done' in dict $entries" + set record 0 + } } else { - ns_log notice "boomerang: no nt_con_st value in $entries" + ns_log notice "boomerang: no value for 'nt_nav_st' or 'nt_req_st' in dict $entries" set record 0 } } @@ -242,7 +331,7 @@ -filename boomerang-[clock format [clock seconds] -format %Y-%m-%d].log } - + # # Some common parameters: # https://docs.soasta.com/whatsinbeacon/#urls @@ -253,19 +342,23 @@ # - r: URL of previous page that Boomerang wrote into a cookie # - u: URL of Page, XHR or SPA route that caused the beacon # - if {![dict exists $entries r]} { - set r "" - } else { - set r [dict get $entries r] + try { + if {![dict exists $entries r]} { + set r "" + } else { + set r [dict get $entries r] + } + set u [dict get $entries u] + set pid [dict get $entries pid] + if {$r ne "" && $r ne $u} { + set r " r $r" + } else { + set r "" + } + ns_log notice "boomerang::record done $record $pid [ns_conn method] u $u$r record $record total [expr {[clock clicks -microseconds] - $t0}] microseconds record [expr {[clock clicks -microseconds] - $t1}] " + } on error {errorMsg} { + ns_log error "boomerang: cleanup lead to error: $errorMsg" } - set u [dict get $entries u] - set pid [dict get $entries pid] - if {$r ne "" && $r ne $u} { - set r " r $r" - } else { - set r "" - } - ns_log notice "boomerang::record done $pid [ns_conn method] u $u$r record $record total [expr {[clock clicks -microseconds] - $t0}] microseconds record [expr {[clock clicks -microseconds] - $t1}] " } } @@ -279,7 +372,7 @@ subsite) or the main subsite. This code makes sure, we can provide a URL on this site. We should distinguish between cases where we provide a URL (e.g. the beacon) or just - include stuff, in which case it works als well for host-node + include stuff, in which case it works as well for host-node entries, which are no subsites..... but these cases are rare enough, such we don't care so far. @@ -313,19 +406,23 @@ Initialize an boomerang widget. } { - #set t0 [clock clicks -microseconds] + set t0 [clock clicks -microseconds] if {$subsite_id eq ""} { set subsite_id [get_relevant_subsite] } - if {$version eq ""} { - set version ${::boomerang::version} - } + set resource_info [resource_info -version $version] + set version [dict get $resource_info configuredVersion] + set enabled_p [parameter::get \ -package_id $subsite_id \ -parameter BoomerangEnabled \ - -default 0] - if {$enabled_p} { + -default 1] + # + # When the package is enabled, and we are not in a "bots" + # connection pool, look in more details. + # + if {$enabled_p && [ns_conn pool] ne "bots"} { # # Check, if we should sample this request # @@ -337,7 +434,7 @@ set sample 1 } - if {[nsv_incr boomerange counter] % $sample == 0} { + if {[nsv_incr boomerang counter] % $sample == 0} { # # Yes, we can! # @@ -348,9 +445,8 @@ -parameter BoomerangBeaconUrl \ -default /boomerang_handler] - set version_info [version_info] - set prefix [dict get $version_info prefix] - foreach jsFile [dict get $version_info jsFiles] { + set prefix [dict get $resource_info prefix] + foreach jsFile [dict get $resource_info jsFiles] { template::head::add_javascript -src ${prefix}/$jsFile } # @@ -375,64 +471,87 @@ # "plugins/usertiming.js", # "plugins/mq.js" # + template::head::add_javascript -src ${prefix}/plugins-$version/navtiming.js + #template::head::add_javascript -src ${prefix}/plugins-$version/rt.js template::head::add_javascript -order 2 -script [subst { BOOMR.init({ beacon_url: "$beaconURL", - log: null + log: null, + NavigationTiming: { + enabled: true, + clearOnBeacon: true + } }); }] } } - #ns_log notice "boomerang::initialize_widget [expr {[clock clicks -microseconds] - $t0}] microseconds" + #ns_log notice "boomerang::initialize_widget (enabled $enabled_p)" \ + "[expr {[clock clicks -microseconds] - $t0}] microseconds" } - ad_proc version_info { + ad_proc resource_info { {-version ""} } { Get information about available version(s) of the - boomerang packages, either from the local file system, or + boomerang packages, either from the local filesystem, or from CDN. } { + variable parameter_info # - # If no version of the boomerange library was specified, + # If no version of the boomerang library was specified, # use the name-spaced variable as default. # if {$version eq ""} { - set version ${::boomerang::version} + dict with parameter_info { + set version [::parameter::get_global_value \ + -package_key $package_key \ + -parameter $parameter_name \ + -default $default_value] + } } # # Provide paths for loading either via resources or CDN # - set resource_prefix [acs_package_root_dir boomerang/www/resources] - set cdn "//cdnjs.cloudflare.com/ajax/libs" + set resourceDir [acs_package_root_dir boomerang/www/resources] + set cdnHost cdnjs.cloudflare.com + set cdn //$cdnHost/ajax/libs - # - # If the resources are not available locally, these will be - # loaded via CDN and the CDN host is set (necessary for CSP). - # The returned "prefix" indicates the place, from where the - # resource will be loaded. - # - if {[file exists $resource_prefix]} { - set prefix /resources/boomerang + if {[file exists $resourceDir/boomerang-$version.js]} { + # + # Local version is installed + # + set prefix /resources/boomerang + set cdnHost "" + set cspMap "" } else { # - # So far there is no CDN form boomerang, we distribute + # So far, there is no CDN form boomerang, we distribute # boomerang.js via static file. # set prefix $cdn/$version/ lappend result host "cdnjs.cloudflare.com" } - + lappend result \ + resourceName "Boomerang" \ + resourceDir $resourceDir \ + versionSegment "" \ cdn $cdn \ + cdnHost $cdnHost \ prefix $prefix \ cssFiles {} \ - jsFiles [list boomerang-${version}.min.js] + jsFiles [list boomerang-${version}.js] \ + extraFiles {} \ + downloadURLs https://github.com/akamai/boomerang/archive/refs/tags/1.737.0.tar.gz \ + cspMap {} \ + urnMap {} \ + parameterInfo $parameter_info \ + configuredVersion $version return $result }