GH-589: improve printing of sub-microsecond intervals

src/Val.cc

@@ -666,6 +666,17 @@ IntervalVal::IntervalVal(double quantity, double units) :
 
 void IntervalVal::ValDescribe(ODesc* d) const
 	{
+	using unit_word = std::pair<double, const char*>;
+
+	constexpr std::array<unit_word, 6> units = {
+		unit_word{ Days, "day" },
+		unit_word{ Hours, "hr" },
+		unit_word{ Minutes, "min" },
+		unit_word{ Seconds, "sec" },
+		unit_word{ Milliseconds, "msec" },
+		unit_word{ Microseconds, "usec" },
+	};
+
 	double v = val.double_val;
 
 	if ( v == 0.0 )
@@ -674,31 +685,55 @@ void IntervalVal::ValDescribe(ODesc* d) const
 		return;
 		}
 
-	int did_one = 0;
+	bool did_one = false;
+	constexpr auto last_idx = units.size() - 1;
 
-#define DO_UNIT(unit, name) \
+	auto approx_equal = [](double a, double b, double tolerance = 1e-6) -> bool
-	if ( v >= unit || v <= -unit ) \
+		{
-		{ \
+		auto v = a - b;
-		double num = double(int(v / unit)); \
+		return v < 0 ? -v < tolerance : v < tolerance;
-		if ( num != 0.0 ) \
+		};
-			{ \
+
-			if ( did_one++ ) \
+	for ( size_t i = 0; i < units.size(); ++i )
-				d->SP(); \
+		{
-			d->Add(num); \
+		auto unit = units[i].first;
-			d->SP(); \
+		auto word = units[i].second;
-			d->Add(name); \
+		double to_print = 0;
-			if ( num != 1.0 && num != -1.0 ) \
+
-				d->Add("s"); \
+		if ( i == last_idx )
-			v -= num * unit; \
+			{
-			} \
+			to_print = v / unit;
+
+			if ( approx_equal(to_print, 0) )
+				{
+				if ( ! did_one )
+					d->Add("0 secs");
+
+				break;
+				}
+			}
+		else
+			{
+			if ( ! (v >= unit || v <= -unit) )
+				continue;
+
+			double num = static_cast<double>(static_cast<int64_t>(v / unit));
+			v -= num * unit;
+			to_print = num;
+			}
+
+		if ( did_one )
+			d->SP();
+
+		d->Add(to_print);
+		d->SP();
+		d->Add(word);
+
+		if ( ! approx_equal(to_print, 1) && ! approx_equal(to_print, -1) )
+			d->Add("s");
+
+		did_one = true;
 		}
-
-	DO_UNIT(Days, "day")
-	DO_UNIT(Hours, "hr")
-	DO_UNIT(Minutes, "min")
-	DO_UNIT(Seconds, "sec")
-	DO_UNIT(Milliseconds, "msec")
-	DO_UNIT(Microseconds, "usec")
 	}
 
 PortVal* PortManager::Get(uint32_t port_num) const

testing/btest/Baseline/core.print-interval/out

@@ -0,0 +1,19 @@
+0 secs
+0.123457 usecs
+-0.123457 usecs
+1.0 msec 234.567891 usecs
+-1.0 msec -234.567891 usecs
+12.0 secs 345.0 msecs 678.912345 usecs
+-12.0 secs -345.0 msecs -678.912345 usecs
+1.0 day 10.0 hrs 17.0 mins 36.0 secs 789.0 msecs 123.449984 usecs
+-1.0 day -10.0 hrs -17.0 mins -36.0 secs -789.0 msecs -123.449984 usecs
+1.001 usecs
+1.0 msec 1 usec
+11.0 msecs
+8.0 days 12.0 hrs
+7.0 hrs 30.0 mins
+6.0 mins 30.0 secs
+5.0 secs 500.0 msecs
+4.0 msecs 500 usecs
+3.5 usecs
+2.0 days 2.0 secs

testing/btest/Baseline/language.expire_subnet/output

@@ -13,15 +13,15 @@ Time: 0 secs
 
 Accessed table nums: two; three
 Accessed table nets: two; zero, three
-Time: 7.0 secs 518.0 msecs 828.0 usecs
+Time: 7.0 secs 518.0 msecs 828.15361 usecs
 
-Expired Num: 4 --> four at 8.0 secs 835.0 msecs 30.0 usecs
+Expired Num: 4 --> four at 8.0 secs 835.0 msecs 30.078888 usecs
-Expired Num: 1 --> one at 8.0 secs 835.0 msecs 30.0 usecs
+Expired Num: 1 --> one at 8.0 secs 835.0 msecs 30.078888 usecs
-Expired Num: 0 --> zero at 8.0 secs 835.0 msecs 30.0 usecs
+Expired Num: 0 --> zero at 8.0 secs 835.0 msecs 30.078888 usecs
-Expired Subnet: 192.168.4.0/24 --> four at 8.0 secs 835.0 msecs 30.0 usecs
+Expired Subnet: 192.168.4.0/24 --> four at 8.0 secs 835.0 msecs 30.078888 usecs
-Expired Subnet: 192.168.1.0/24 --> one at 8.0 secs 835.0 msecs 30.0 usecs
+Expired Subnet: 192.168.1.0/24 --> one at 8.0 secs 835.0 msecs 30.078888 usecs
-Expired Subnet: 192.168.0.0/16 --> zero at 15.0 secs 150.0 msecs 681.0 usecs
+Expired Subnet: 192.168.0.0/16 --> zero at 15.0 secs 150.0 msecs 681.018829 usecs
-Expired Subnet: 192.168.3.0/24 --> three at 15.0 secs 150.0 msecs 681.0 usecs
+Expired Subnet: 192.168.3.0/24 --> three at 15.0 secs 150.0 msecs 681.018829 usecs
-Expired Subnet: 192.168.2.0/24 --> two at 15.0 secs 150.0 msecs 681.0 usecs
+Expired Subnet: 192.168.2.0/24 --> two at 15.0 secs 150.0 msecs 681.018829 usecs
-Expired Num: 2 --> two at 15.0 secs 150.0 msecs 681.0 usecs
+Expired Num: 2 --> two at 15.0 secs 150.0 msecs 681.018829 usecs
-Expired Num: 3 --> three at 15.0 secs 150.0 msecs 681.0 usecs
+Expired Num: 3 --> three at 15.0 secs 150.0 msecs 681.018829 usecs

testing/btest/Baseline/plugins.hooks/output

@@ -274,7 +274,7 @@
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> <no result>
-0.000000   MetaHookPost  CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
+0.000000   MetaHookPost  CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Broker::LOG)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Cluster::LOG)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Config::LOG)) -> <no result>
@@ -455,7 +455,7 @@
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> <no result>
-0.000000   MetaHookPost  CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
+0.000000   MetaHookPost  CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
 0.000000   MetaHookPost  CallFunction(NetControl::check_plugins, <frame>, ()) -> <no result>
 0.000000   MetaHookPost  CallFunction(NetControl::init, <null>, ()) -> <no result>
 0.000000   MetaHookPost  CallFunction(Notice::want_pp, <frame>, ()) -> <no result>
@@ -1169,7 +1169,7 @@
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]))
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]))
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]))
-0.000000   MetaHookPre   CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T]))
+0.000000   MetaHookPre   CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T]))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Broker::LOG))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Cluster::LOG))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Config::LOG))
@@ -1350,7 +1350,7 @@
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]))
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]))
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]))
-0.000000   MetaHookPre   CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T]))
+0.000000   MetaHookPre   CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T]))
 0.000000   MetaHookPre   CallFunction(NetControl::check_plugins, <frame>, ())
 0.000000   MetaHookPre   CallFunction(NetControl::init, <null>, ())
 0.000000   MetaHookPre   CallFunction(Notice::want_pp, <frame>, ())
@@ -2063,7 +2063,7 @@
 0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])
 0.000000 | HookCallFunction Log::__create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])
 0.000000 | HookCallFunction Log::__create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])
-0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T])
+0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T])
 0.000000 | HookCallFunction Log::add_default_filter(Broker::LOG)
 0.000000 | HookCallFunction Log::add_default_filter(Cluster::LOG)
 0.000000 | HookCallFunction Log::add_default_filter(Config::LOG)
@@ -2244,7 +2244,7 @@
 0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])
 0.000000 | HookCallFunction Log::create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])
 0.000000 | HookCallFunction Log::create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])
-0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T])
+0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T])
 0.000000 | HookCallFunction NetControl::check_plugins()
 0.000000 | HookCallFunction NetControl::init()
 0.000000 | HookCallFunction Notice::want_pp()
@@ -2678,7 +2678,7 @@
 0.000000 | HookLoadFile  base<...>/xmpp
 0.000000 | HookLoadFile  base<...>/zeek.bif.zeek
 0.000000 | HookLogInit   packet_filter 1/1 {ts (time), node (string), filter (string), init (bool), success (bool)}
-0.000000 | HookLogWrite  packet_filter [ts=1565053246.404549, node=zeek, filter=ip or not ip, init=T, success=T]
+0.000000 | HookLogWrite  packet_filter [ts=1569285011.394497, node=zeek, filter=ip or not ip, init=T, success=T]
 0.000000 | HookQueueEvent NetControl::init()
 0.000000 | HookQueueEvent filter_change_tracking()
 0.000000 | HookQueueEvent zeek_init()
@@ -3006,9 +3006,9 @@
 1362692527.009775   MetaHookPost  CallFunction(HTTP::code_in_range, <frame>, (200, 100, 199)) -> <no result>
 1362692527.009775   MetaHookPost  CallFunction(HTTP::get_file_handle, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, ntp=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smb_state=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], F)) -> <no result>
 1362692527.009775   MetaHookPost  CallFunction(HTTP::set_state, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, ntp=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smb_state=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], F)) -> <no result>
-1362692527.009775   MetaHookPost  CallFunction(Log::__write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.0 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])) -> <no result>
+1362692527.009775   MetaHookPost  CallFunction(Log::__write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.975693 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])) -> <no result>
 1362692527.009775   MetaHookPost  CallFunction(Log::__write, <frame>, (HTTP::LOG, [ts=1362692526.939527, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1])) -> <no result>
-1362692527.009775   MetaHookPost  CallFunction(Log::write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.0 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])) -> <no result>
+1362692527.009775   MetaHookPost  CallFunction(Log::write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.975693 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])) -> <no result>
 1362692527.009775   MetaHookPost  CallFunction(Log::write, <frame>, (HTTP::LOG, [ts=1362692526.939527, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1])) -> <no result>
 1362692527.009775   MetaHookPost  CallFunction(cat, <frame>, (Analyzer::ANALYZER_HTTP, 1362692526.869344, F, 1, 1, 141.142.228.5:59856 > 192.150.187.43:80)) -> <no result>
 1362692527.009775   MetaHookPost  CallFunction(file_sniff, <null>, ([id=FakNcS1Jfe01uljb3, parent_id=<uninitialized>, source=HTTP, is_orig=F, conns={[[orig_h=141.142.228.5, orig_p=59856<...>/plain]], inferred=T])) -> <no result>
@@ -3035,9 +3035,9 @@
 1362692527.009775   MetaHookPre   CallFunction(HTTP::code_in_range, <frame>, (200, 100, 199))
 1362692527.009775   MetaHookPre   CallFunction(HTTP::get_file_handle, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, ntp=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smb_state=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], F))
 1362692527.009775   MetaHookPre   CallFunction(HTTP::set_state, <frame>, ([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, ntp=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smb_state=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], F))
-1362692527.009775   MetaHookPre   CallFunction(Log::__write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.0 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>]))
+1362692527.009775   MetaHookPre   CallFunction(Log::__write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.975693 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>]))
 1362692527.009775   MetaHookPre   CallFunction(Log::__write, <frame>, (HTTP::LOG, [ts=1362692526.939527, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]))
-1362692527.009775   MetaHookPre   CallFunction(Log::write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.0 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>]))
+1362692527.009775   MetaHookPre   CallFunction(Log::write, <frame>, (Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.975693 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>]))
 1362692527.009775   MetaHookPre   CallFunction(Log::write, <frame>, (HTTP::LOG, [ts=1362692526.939527, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]))
 1362692527.009775   MetaHookPre   CallFunction(cat, <frame>, (Analyzer::ANALYZER_HTTP, 1362692526.869344, F, 1, 1, 141.142.228.5:59856 > 192.150.187.43:80))
 1362692527.009775   MetaHookPre   CallFunction(file_sniff, <null>, ([id=FakNcS1Jfe01uljb3, parent_id=<uninitialized>, source=HTTP, is_orig=F, conns={[[orig_h=141.142.228.5, orig_p=59856<...>/plain]], inferred=T]))
@@ -3065,9 +3065,9 @@
 1362692527.009775 | HookCallFunction HTTP::code_in_range(200, 100, 199)
 1362692527.009775 | HookCallFunction HTTP::get_file_handle([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, ntp=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smb_state=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], F)
 1362692527.009775 | HookCallFunction HTTP::set_state([id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1]}, current_request=1, current_response=1, trans_depth=1], irc=<uninitialized>, krb=<uninitialized>, modbus=<uninitialized>, mysql=<uninitialized>, ntlm=<uninitialized>, ntp=<uninitialized>, radius=<uninitialized>, rdp=<uninitialized>, rfb=<uninitialized>, sip=<uninitialized>, sip_state=<uninitialized>, snmp=<uninitialized>, smb_state=<uninitialized>, smtp=<uninitialized>, smtp_state=<uninitialized>, socks=<uninitialized>, ssh=<uninitialized>, syslog=<uninitialized>], F)
-1362692527.009775 | HookCallFunction Log::__write(Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.0 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])
+1362692527.009775 | HookCallFunction Log::__write(Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.975693 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])
 1362692527.009775 | HookCallFunction Log::__write(HTTP::LOG, [ts=1362692526.939527, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1])
-1362692527.009775 | HookCallFunction Log::write(Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.0 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])
+1362692527.009775 | HookCallFunction Log::write(Files::LOG, [ts=1362692527.009512, fuid=FakNcS1Jfe01uljb3, tx_hosts={192.150.187.43}, rx_hosts={141.142.228.5}, conn_uids={CHhAvVGS1DHFjwGM9}, source=HTTP, depth=0, analyzers={}, mime_type=text/plain, filename=<uninitialized>, duration=262.975693 usecs, local_orig=<uninitialized>, is_orig=F, seen_bytes=4705, total_bytes=4705, missing_bytes=0, overflow_bytes=0, timedout=F, parent_fuid=<uninitialized>, md5=<uninitialized>, sha1=<uninitialized>, sha256=<uninitialized>, x509=<uninitialized>, extracted=<uninitialized>, extracted_cutoff=<uninitialized>, extracted_size=<uninitialized>])
 1362692527.009775 | HookCallFunction Log::write(HTTP::LOG, [ts=1362692526.939527, uid=CHhAvVGS1DHFjwGM9, id=[orig_h=141.142.228.5, orig_p=59856<...>/plain], current_entity=<uninitialized>, orig_mime_depth=1, resp_mime_depth=1])
 1362692527.009775 | HookCallFunction cat(Analyzer::ANALYZER_HTTP, 1362692526.869344, F, 1, 1, 141.142.228.5:59856 > 192.150.187.43:80)
 1362692527.009775 | HookCallFunction file_sniff([id=FakNcS1Jfe01uljb3, parent_id=<uninitialized>, source=HTTP, is_orig=F, conns={[[orig_h=141.142.228.5, orig_p=59856<...>/plain]], inferred=T])

testing/btest/core/print-interval.zeek

@@ -0,0 +1,32 @@
+# @TEST-EXEC: zeek -b %INPUT >out
+# @TEST-EXEC: btest-diff out
+
+function mult10k(p: interval, n: interval, i: count &default=0)
+	{
+	if ( i == 4 )
+		return;
+
+	print p;
+	print n;
+	mult10k(p * 10000, n * 10000, i + 1);
+	}
+
+local d = 0.12345678912345 usecs;
+local nd = -d;
+print 0sec;
+mult10k(d, nd);
+
+d = 1.001 usec;
+print d;
+print d * 1000;
+
+print 1.1usec * 10000;
+
+print 8.5 days;
+print 7.5 hrs;
+print 6.5 mins;
+print 5.5 secs;
+print 4.5 msecs;
+print 3.5 usecs;
+
+print 2 days + 2 secs;