boomerang::handler proc record (public)

 boomerang::handler record -ns_set ns_set  -peeraddr peeraddr 

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

Switches:

-ns_set (required)

-peeraddr (required)

Testcases:

No testcase defined.

Source code:

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"
}

XQL Not present:

Generic, PostgreSQL, Oracle