---

Don't quote the following boomerang attributes when output format is JSON.

Defined in packages/xotcl-core/tcl/01-debug-procs.tcl

Class Relations

• class: ::nx::Object

::nx::Object create ::boomerang::handler

Methods (to be applied on the object)

• record (scripted, public)

   boomerang::handler record -ns_set ns_set  -peeraddr peeraddr 

  Switches:

  -ns_set (required)

  -peeraddr (required)

  Testcases:

  No testcase defined.

  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 variables are provided"
      return
  }
  
  #
  # 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] && [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.
      #
      # 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]}]
  
          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]}]
          }
  
          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]
              }
          }
          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]}]
          }
  
          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 value for 'nt_nav_st' or 'nt_req_st' in dict $entries"
          set record 0
      }
  }
  #
  # Drop most Navigation Timing timestamps, since we have
  # the relative times (might require more fine tuning).
  #
  foreach field {
      nt_con_end
      nt_con_st
      nt_dns_end
      nt_dns_st
      nt_domcomp
      nt_domcontloaded_end
      nt_domcontloaded_st
      nt_domint
      nt_domloading
      nt_fet_st
      nt_load_end
      nt_load_st
      nt_res_st
      nt_ssl_st
      nt_unload_end
      nt_unload_st
  } {
      dict unset entries $field
  }
  set t1 [clock clicks -microseconds]
  
  #
  # dict is finished, now record the data when requested
  #
  if {$record} {
  
      :log_to_file  -content [:as_json $entries]  -filename boomerang-[clock format [clock seconds] -format %Y-%m-%d].log
  
  }
  
  #
  # Some common parameters:
  # https://docs.soasta.com/whatsinbeacon/#urls
  #
  #  - nu:  URL clicked, if this beacon was a result of a click
  #  - pgu: Page URL if different from u
  #  - r2:  Referrer of current page if different from r
  #  - r:   URL of previous page that Boomerang wrote into a cookie
  #  - u:   URL of Page, XHR or SPA route that caused the beacon
  #
  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"
  }

---