Copilot commented on code in PR #12885:
URL: https://github.com/apache/trafficserver/pull/12885#discussion_r2805495469
##########
doc/admin-guide/logging/formatting.en.rst:
##########
@@ -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:
+
+ 0. tls_handshake
+ 0. ua_begin
+ 0. ua_first_read
+ 0. ua_read_header_done
+ 0. cache_open_read_begin
+ 0. cache_open_read_end
+ 0. cache_open_write_begin
+ 0. cache_open_write_end
+ 0. dns_lookup_begin
+ 0. dns_lookup_end
+ 0. server_connect
+ 0. server_connect_end
+ 0. server_first_read
+ 0. server_read_header_done
+ 0. server_close
+ 0. ua_write
+ 0. ua_close
+ 0. sm_finish
+ 0. plugin_active
+ 0. plugin_total
Review Comment:
The documentation uses "0." for all items, which will render all items as
"0." in the generated documentation. This should be a properly numbered list
starting from "1." or use an unordered list with "-" or "*" instead. Since
these are CSV field positions, a numbered list starting from "1." would be most
appropriate.
```suggestion
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
```
##########
src/proxy/logging/LogAccess.cc:
##########
@@ -3494,6 +3495,43 @@ 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");
Review Comment:
The null terminator should not be explicitly printed to the BufferWriter.
The bw.view() method returns a string_view of the current buffer content, and
printing "\0" adds an actual backslash and zero character to the buffer instead
of a null terminator. Remove this line as the marshal_str function will handle
null termination properly.
```suggestion
```
##########
tests/gold_tests/logging/log-mstsms.test.py:
##########
@@ -0,0 +1,120 @@
+'''
+'''
+# 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
+
+
+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, "Check comma count", "Command count doesn't match expected
value"
Review Comment:
The error message returned on success doesn't match the actual check
performed. The message "Command count doesn't match expected value" should be
"Comma count matches expected value" or similar success message, since this is
the True return case.
```suggestion
return True, "Check comma count", "Comma count matches expected value"
```
##########
src/proxy/logging/LogAccess.cc:
##########
@@ -3494,6 +3495,43 @@ 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();
+
+ if (nullptr != buf) {
+ marshal_str(buf, view.data(), view.length());
+ }
+ return view.length();
Review Comment:
The marshal_str function expects the third parameter to be the padded length
(including space for null terminator and alignment), not just the string
length. The return value should also be the padded length for consistency with
other marshal functions. Use padded_length(view.length() + 1) instead of
view.length() to properly calculate the padded buffer size including the null
terminator.
```suggestion
auto const view = bw.view();
auto const padded_len = padded_length(view.length() + 1);
if (nullptr != buf) {
marshal_str(buf, view.data(), padded_len);
}
return padded_len;
```
##########
src/proxy/logging/LogField.cc:
##########
@@ -522,6 +529,8 @@ LogField::updateField(LogAccess *lad, char *buf, int len)
unsigned
LogField::marshal(LogAccess *lad, char *buf)
{
+ Dbg(dbg_ctl_log_field_hash, "marshal_len");
Review Comment:
The debug message says "marshal_len" but this is the marshal function, not
marshal_len. The message should be "marshal" to accurately reflect which
function is being called.
```suggestion
Dbg(dbg_ctl_log_field_hash, "marshal");
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
