This is an automated email from the ASF dual-hosted git repository.
bnolsen pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/master by this push:
new ddc7c23e72 add mstsms log field, slow log as a csv field (#12885)
ddc7c23e72 is described below
commit ddc7c23e72f0ad324bb956ed674571d5a004bfae
Author: Brian Olsen <[email protected]>
AuthorDate: Sat Feb 21 09:37:53 2026 -0700
add mstsms log field, slow log as a csv field (#12885)
* add mstsms log field, slow log as a csv field
* removed call from marshal_len since special expansion not needed
* removal of more uncessary log reroutes
* remove final mstsms container reference
---------
Co-authored-by: Brian Olsen <[email protected]>
---
doc/admin-guide/logging/formatting.en.rst | 125 +++++++++++++++++-----------
include/proxy/logging/LogAccess.h | 18 ++--
src/proxy/logging/Log.cc | 4 +
src/proxy/logging/LogAccess.cc | 39 +++++++++
tests/gold_tests/logging/log-mstsms.test.py | 121 +++++++++++++++++++++++++++
5 files changed, 251 insertions(+), 56 deletions(-)
diff --git a/doc/admin-guide/logging/formatting.en.rst
b/doc/admin-guide/logging/formatting.en.rst
index b85e6407ad..ba74dcb8f3 100644
--- a/doc/admin-guide/logging/formatting.en.rst
+++ b/doc/admin-guide/logging/formatting.en.rst
@@ -756,6 +756,7 @@ Timestamps and Durations
.. _crat:
.. _ms:
.. _msdms:
+.. _mstsms:
.. _stms:
.. _stmsh:
.. _stmsf:
@@ -775,54 +776,56 @@ Other fields in this category provide variously formatted
timestamps of
particular events within the current transaction (e.g. the time at which a
client request was received by |TS|).
-===== ======================= =================================================
-Field Source Description
-===== ======================= =================================================
-cqtd Client Request Client request timestamp. Specifies the date of
- the client request in the format ``YYYY-MM-DD``
- (four digit year, two digit month, two digit day
- - with leading zeros as necessary for the latter
- two).
-cqtn Client Request Client request timestamp in the Netscape
- timestamp format.
-cqtq Client Request The time at which the client request was received
- expressed as fractional (floating point) seconds
- since midnight January 1, 1970 UTC (epoch), with
- millisecond resolution.
-cqts Client Request Same as cqtq_, but as an integer without
- sub-second resolution.
-cqth Client Request Same as cqts_, but represented in hexadecimal.
-cqtt Client Request Client request timestamp in the 24-hour format
- ``hh:mm:ss`` (two digit hour, minutes, and
- seconds - with leading zeros as necessary).
-crat Origin Response Retry-After time in seconds if specified in the
- origin server response.
-ms Proxy Timestamp in milliseconds of a specific milestone
- for this request. See note below about specifying
- which milestone to use.
-msdms Proxy Difference in milliseconds between the timestamps
- of two milestones. See note below about
- specifying which milestones to use.
-stms Proxy-Origin Connection Time (in milliseconds) spent accessing the origin
- server. Measured from the time the connection
- between proxy and origin is established to the
- time it was closed.
-stmsh Proxy-Origin Connection Same as stms_, but represented in hexadecimal.
-stmsf Proxy-Origin Connection Same as stms_, but in fractional (floating point)
- seconds.
-sts Proxy-Origin Connection Same as stms_, but in integer seconds (no
- sub-second precision).
-ttms Client-Proxy Connection Time in milliseconds spent by |TS| processing the
- entire client request. Measured from the time the
- connection between the client and |TS| proxy was
- established until the last byte of the proxy
- response was delivered to the client.
-ttmsh Client-Proxy Connection Same as ttms_, but represented in hexadecimal.
-ttmsf Client-Proxy Connection Same as ttms_, but in fraction (floating point)
- seconds.
-tts Client Request Same as ttms_, but in integer seconds (no
- sub-second precision).
-===== ======================= =================================================
+====== =======================
=================================================
+Field Source Description
+====== =======================
=================================================
+cqtd Client Request Client request timestamp. Specifies the date of
+ the client request in the format ``YYYY-MM-DD``
+ (four digit year, two digit month, two digit day
+ - with leading zeros as necessary for the latter
+ two).
+cqtn Client Request Client request timestamp in the Netscape
+ timestamp format.
+cqtq Client Request The time at which the client request was
received
+ expressed as fractional (floating point) seconds
+ since midnight January 1, 1970 UTC (epoch), with
+ millisecond resolution.
+cqts Client Request Same as cqtq_, but as an integer without
+ sub-second resolution.
+cqth Client Request Same as cqts_, but represented in hexadecimal.
+cqtt Client Request Client request timestamp in the 24-hour format
+ ``hh:mm:ss`` (two digit hour, minutes, and
+ seconds - with leading zeros as necessary).
+crat Origin Response Retry-After time in seconds if specified in the
+ origin server response.
+ms Proxy Timestamp in milliseconds of a specific
milestone
+ for this request. See note below about
specifying
+ which milestone to use.
+msdms Proxy Difference in milliseconds between the
timestamps
+ of two milestones. See note below about
+ specifying which milestones to use.
+mstsms Proxy Slow log report in milliseconds as CSV.
+ See note below about what timestamps are used.
+stms Proxy-Origin Connection Time (in milliseconds) spent accessing the
origin
+ server. Measured from the time the connection
+ between proxy and origin is established to the
+ time it was closed.
+stmsh Proxy-Origin Connection Same as stms_, but represented in hexadecimal.
+stmsf Proxy-Origin Connection Same as stms_, but in fractional (floating
point)
+ seconds.
+sts Proxy-Origin Connection Same as stms_, but in integer seconds (no
+ sub-second precision).
+ttms Client-Proxy Connection Time in milliseconds spent by |TS| processing
the
+ entire client request. Measured from the time
the
+ connection between the client and |TS| proxy was
+ established until the last byte of the proxy
+ response was delivered to the client.
+ttmsh Client-Proxy Connection Same as ttms_, but represented in hexadecimal.
+ttmsf Client-Proxy Connection Same as ttms_, but in fraction (floating point)
+ seconds.
+tts Client Request Same as ttms_, but in integer seconds (no
+ sub-second precision).
+====== =======================
=================================================
.. note::
@@ -837,6 +840,32 @@ tts Client Request Same as ttms_, but in
integer seconds (no
For more information on transaction milestones in |TS|, refer to the
documentation on :func:`TSHttpTxnMilestoneGet`.
+.. note::
+
+ A full milestone report can be generated as a CSV string that matches
+ the example slow log. Fields are:
+
+ 1. tls_handshake
+ 2. ua_begin
+ 3. ua_first_read
+ 4. ua_read_header_done
+ 5. cache_open_read_begin
+ 6. cache_open_read_end
+ 7. cache_open_write_begin
+ 8. cache_open_write_end
+ 9. dns_lookup_begin
+ 10. dns_lookup_end
+ 11. server_connect
+ 12. server_connect_end
+ 13. server_first_read
+ 14. server_read_header_done
+ 15. server_close
+ 16. ua_write
+ 17. ua_close
+ 18. sm_finish
+ 19. plugin_active
+ 20. plugin_total
+
.. _admin-logging-fields-urls:
URLs, Schemes, and Paths
diff --git a/include/proxy/logging/LogAccess.h
b/include/proxy/logging/LogAccess.h
index 7cdf8ed48b..cfe3bf557f 100644
--- a/include/proxy/logging/LogAccess.h
+++ b/include/proxy/logging/LogAccess.h
@@ -296,14 +296,16 @@ public:
//
// milestones access
//
- int marshal_milestone(TSMilestonesType ms, char *buf);
- int marshal_milestone_fmt_sec(TSMilestonesType ms, char *buf);
- int marshal_milestone_fmt_squid(TSMilestonesType ms, char *buf);
- int marshal_milestone_fmt_netscape(TSMilestonesType ms, char *buf);
- int marshal_milestone_fmt_date(TSMilestonesType ms, char *buf);
- int marshal_milestone_fmt_time(TSMilestonesType ms, char *buf);
- int marshal_milestone_fmt_ms(TSMilestonesType ms, char *buf);
- int marshal_milestone_diff(TSMilestonesType ms1, TSMilestonesType ms2, char
*buf);
+ int marshal_milestone(TSMilestonesType ms, char *buf);
+ int marshal_milestone_fmt_sec(TSMilestonesType ms, char *buf);
+ int marshal_milestone_fmt_squid(TSMilestonesType ms, char *buf);
+ int marshal_milestone_fmt_netscape(TSMilestonesType ms, char *buf);
+ int marshal_milestone_fmt_date(TSMilestonesType ms, char *buf);
+ int marshal_milestone_fmt_time(TSMilestonesType ms, char *buf);
+ int marshal_milestone_fmt_ms(TSMilestonesType ms, char *buf);
+ int marshal_milestone_diff(TSMilestonesType ms1, TSMilestonesType ms2, char
*buf);
+ int marshal_milestones_csv(char *buf);
+
void set_http_header_field(LogField::Container container, char *field, char
*buf, int len);
//
// unmarshalling routines
diff --git a/src/proxy/logging/Log.cc b/src/proxy/logging/Log.cc
index 4ac59bf679..3bca7c5333 100644
--- a/src/proxy/logging/Log.cc
+++ b/src/proxy/logging/Log.cc
@@ -858,6 +858,10 @@ Log::init_fields()
global_field_list.add(field, false);
field_symbol_hash.emplace("sshv", field);
+ field = new LogField("milestones_csv", "mstsms", LogField::STRING,
&LogAccess::marshal_milestones_csv, &LogAccess::unmarshal_str);
+ global_field_list.add(field, false);
+ field_symbol_hash.emplace("mstsms", field);
+
field = new LogField("server_resp_time", "stms", LogField::sINT,
&LogAccess::marshal_server_resp_time_ms,
&LogAccess::unmarshal_int_to_str);
global_field_list.add(field, false);
diff --git a/src/proxy/logging/LogAccess.cc b/src/proxy/logging/LogAccess.cc
index 908ec8c22f..d04082fdce 100644
--- a/src/proxy/logging/LogAccess.cc
+++ b/src/proxy/logging/LogAccess.cc
@@ -30,6 +30,7 @@
#include "iocore/utils/Machine.h"
#include "proxy/logging/LogFormat.h"
#include "proxy/logging/LogBuffer.h"
+#include "swoc/BufferWriter.h"
#include "tscore/Encoding.h"
#include "../private/SSLProxySession.h"
#include "tscore/ink_inet.h"
@@ -3494,6 +3495,44 @@ LogAccess::marshal_milestone_diff(TSMilestonesType ms1,
TSMilestonesType ms2, ch
return INK_MIN_ALIGN;
}
+int
+LogAccess::marshal_milestones_csv(char *buf)
+{
+ Dbg(dbg_ctl_log_unmarshal_data, "marshal_milestones_csv");
+
+ swoc::LocalBufferWriter<256> bw;
+
+ bw.print("{}",
m_http_sm->milestones.difference_msec(TS_MILESTONE_TLS_HANDSHAKE_START,
TS_MILESTONE_TLS_HANDSHAKE_END));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_UA_BEGIN));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_UA_FIRST_READ));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_UA_READ_HEADER_DONE));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_CACHE_OPEN_READ_BEGIN));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_CACHE_OPEN_READ_END));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_CACHE_OPEN_WRITE_BEGIN));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_CACHE_OPEN_WRITE_END));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_DNS_LOOKUP_BEGIN));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_DNS_LOOKUP_END));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_SERVER_CONNECT));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_SERVER_CONNECT_END));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_SERVER_FIRST_READ));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_SERVER_READ_HEADER_DONE));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_SERVER_CLOSE));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_UA_BEGIN_WRITE));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_UA_CLOSE));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_SM_FINISH));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_PLUGIN_ACTIVE));
+ bw.print(",{}", m_http_sm->milestones.difference_msec(TS_MILESTONE_SM_START,
TS_MILESTONE_PLUGIN_TOTAL));
+ bw.print("\0");
+
+ auto const view = bw.view();
+ int const len = LogAccess::padded_strlen(view.data());
+
+ if (nullptr != buf) {
+ marshal_str(buf, view.data(), len);
+ }
+ return len;
+}
+
void
LogAccess::set_http_header_field(LogField::Container container, char *field,
char *buf, int len)
{
diff --git a/tests/gold_tests/logging/log-mstsms.test.py
b/tests/gold_tests/logging/log-mstsms.test.py
new file mode 100644
index 0000000000..a8831e02e7
--- /dev/null
+++ b/tests/gold_tests/logging/log-mstsms.test.py
@@ -0,0 +1,121 @@
+'''
+'''
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements. See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership. The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License. You may obtain a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import os
+
+Test.Summary = '''
+Test log fields.
+'''
+
+ts = Test.MakeATSProcess("ts", enable_cache=True)
+server = Test.MakeOriginServer("server")
+
+request_header = {'timestamp': 100, "headers": "GET /test-1 HTTP/1.1\r\nHost:
test-1\r\n\r\n", "body": ""}
+response_header = {
+ 'timestamp': 100,
+ "headers":
+ "HTTP/1.1 200 OK\r\nTest: 1\r\nContent-Type:
application/json\r\nConnection: close\r\nContent-Type:
application/json\r\nTransfer-Encoding: chunked\r\n\r\n",
+ "body": "Test 1"
+}
+server.addResponse("sessionlog.json", request_header, response_header)
+server.addResponse(
+ "sessionlog.json", {
+ 'timestamp': 101,
+ "headers": "GET /test-2 HTTP/1.1\r\nHost: test-2\r\n\r\n",
+ "body": ""
+ }, {
+ 'timestamp': 101,
+ "headers":
+ "HTTP/1.1 200 OK\r\nTest: 2\r\nContent-Type:
application/jason\r\nConnection: close\r\nContent-Type:
application/json\r\n\r\n",
+ "body": "Test 2"
+ })
+server.addResponse(
+ "sessionlog.json", {
+ 'timestamp': 102,
+ "headers": "GET /test-3 HTTP/1.1\r\nHost: test-3\r\n\r\n",
+ "body": ""
+ }, {
+ 'timestamp': 102,
+ "headers": "HTTP/1.1 200 OK\r\nTest: 3\r\nConnection:
close\r\nContent-Type: application/json\r\n\r\n",
+ "body": "Test 3"
+ })
+
+nameserver = Test.MakeDNServer("dns", default='127.0.0.1')
+
+ts.Disk.records_config.update(
+ {
+ 'proxy.config.diags.debug.enabled': 1,
+ 'proxy.config.diags.debug.tags': 'http|log',
+ # 'proxy.config.net.connections_throttle': 100,
+ 'proxy.config.dns.nameservers':
f"127.0.0.1:{nameserver.Variables.Port}",
+ 'proxy.config.dns.resolv_conf': 'NULL',
+ })
+# setup some config file for this server
+ts.Disk.remap_config.AddLine('map /
http://localhost:{}/'.format(server.Variables.Port))
+
+ts.Disk.logging_yaml.AddLines(
+ '''
+logging:
+ formats:
+ - name: custom
+ format: 'mstsms:%<mstsms>'
+ logs:
+ - filename: field-mstsms
+ format: custom
+'''.split("\n"))
+
+# first test is a miss for default
+tr = Test.AddTestRun()
+# Wait for the micro server
+tr.Processes.Default.StartBefore(server)
+tr.Processes.Default.StartBefore(nameserver)
+# Delay on readiness of our ssl ports
+tr.Processes.Default.StartBefore(Test.Processes.ts)
+
+tr.MakeCurlCommand('--verbose --header "Host: test-1"
http://localhost:{0}/test-1'.format(ts.Variables.port), ts=ts)
+tr.Processes.Default.ReturnCode = 0
+
+tr = Test.AddTestRun()
+tr.MakeCurlCommand('--verbose --header "Host: test-2"
http://localhost:{0}/test-2'.format(ts.Variables.port), ts=ts)
+tr.Processes.Default.ReturnCode = 0
+
+tr = Test.AddTestRun()
+tr.MakeCurlCommand('--verbose --header "Host: test-3"
http://localhost:{0}/test-3'.format(ts.Variables.port), ts=ts)
+tr.Processes.Default.ReturnCode = 0
+
+
+# check comma count and ensure last character is a digit
+def check_lines(path):
+ with open(path, 'r') as file:
+ for line_num, line in enumerate(file, 1):
+ line = line.rstrip('\n')
+ comma_count = line.count(',')
+ if comma_count != 19:
+ return False, "Check comma count", f"Expected 19 commas, got
{comma_count}"
+ if not line[-1].isdigit():
+ return False, "Check last char", f"Expected last character to
be a digit got '{line[-1]}'"
+ return True, "", ""
+
+
+logpath = os.path.join(ts.Variables.LOGDIR, 'field-mstsms.log')
+
+# Wait for log file to appear, then wait one extra second to make sure TS is
done writing it.
+tr = Test.AddTestRun()
+tr.Processes.Default.Command = (os.path.join(Test.Variables.AtsTestToolsDir,
'condwait') + ' 60 1 -f ' + logpath)
+#tr.Processes.Default.ReturnCode = 0
+tr.Streams.All.Content = Testers.Lambda(lambda info, tester:
check_lines(logpath))
