Unaccurate timestamps in APIM Policies

Manuel Tospann 1 Reputation point
2024-06-18T10:58:22.0166667+00:00

I noticed that the timestamps in APIM Policies look like a lot of things are running in parallel.

I have the following policy:

<policies>
    <inbound>
        <set-variable name="start_time" value="@(DateTime.UtcNow.ToString("o"))" />
        <xsl-transform>
			[...]
		</xsl-transform>
        <base />
        <set-variable name="end_time" value="@(DateTime.UtcNow.ToString("o"))" />
        <set-backend-service base-url="[...]" />
    </inbound>
    <backend>
        <base />
    </backend>
    <outbound>
        <base />
        <set-variable name="outbound_time" value="@(DateTime.UtcNow.ToString("o"))" />
    </outbound>
    <on-error>
        <base />
    </on-error>
</policies>

The sanitized trace shows this:

{
   "serviceName":"[...]",
   "traceEntries":{
      "inbound":[
         {
            "source":"cors",
            "timestamp":"2024-06-18T10:43:37.9545915Z",
            "elapsed":"00:00:00.0050615",
            "data":"Origin header was missing or empty and the request was classified as not cross-domain. CORS policy was not applied."
         },
         {
            "source":"set-variable",
            "timestamp":"2024-06-18T10:43:37.9545915Z",
            "elapsed":"00:00:00.0050681",
            "data":{
               "message":"Expression was successfully evaluated.",
               "expression":"DateTime.UtcNow.ToString(\"o\")",
               "value":"2024-06-18T10:43:37.9545915Z"
            }
         },
         {
            "source":"set-variable",
            "timestamp":"2024-06-18T10:43:37.9545915Z",
            "elapsed":"00:00:00.0050768",
            "data":{
               "message":"Context variable was successfully set.",
               "name":"start_time",
               "value":"2024-06-18T10:43:37.9545915Z"
            }
         },
         {
            "source":"xsl-transform",
            "timestamp":"2024-06-18T10:43:37.9701951Z",
            "elapsed":"00:00:00.0078287",
            "data":"XSL Transform policy was applied. Original Content-Length header updated to new value. "
         },
         {
            "source":"set-variable",
            "timestamp":"2024-06-18T10:43:37.9701951Z",
            "elapsed":"00:00:00.0078450",
            "data":{
               "message":"Expression was successfully evaluated.",
               "expression":"DateTime.UtcNow.ToString(\"o\")",
               "value":"2024-06-18T10:43:37.9701951Z"
            }
         },
         {
            "source":"set-variable",
            "timestamp":"2024-06-18T10:43:37.9701951Z",
            "elapsed":"00:00:00.0078632",
            "data":{
               "message":"Context variable was successfully set.",
               "name":"end_time",
               "value":"2024-06-18T10:43:37.9701951Z"
            }
         },
         {
            "source":"set-backend-service",
            "timestamp":"2024-06-18T10:43:37.9701951Z",
            "elapsed":"00:00:00.0078743",
            "data":{
               "message":"Backend service URL was changed.",
               "oldBackendServiceUrl":"",
               "newBackendServiceUrl":"[...]",
               "request":{
                  "url":"[...]"
               }
            }
         }
      ],
      "backend":[
         {
            "source":"forward-request",
            "timestamp":"2024-06-18T10:43:37.9701951Z",
            "elapsed":"00:00:00.0080680",
            [...]
         }
      ],
      "outbound":[
         {
            "source":"set-variable",
            "timestamp":"2024-06-18T10:43:38.6108878Z",
            "elapsed":"00:00:00.6624263",
            "data":{
               "message":"Expression was successfully evaluated.",
               "expression":"DateTime.UtcNow.ToString(\"o\")",
               "value":"2024-06-18T10:43:38.6108878Z"
            }
         },
         {
            "source":"set-variable",
            "timestamp":"2024-06-18T10:43:38.6108878Z",
            "elapsed":"00:00:00.6624385",
            "data":{
               "message":"Context variable was successfully set.",
               "name":"outbound_time",
               "value":"2024-06-18T10:43:38.6108878Z"
            }
         },
         {
            "source":"transfer-response",
            "timestamp":"2024-06-18T10:43:38.6108878Z",
            "elapsed":"00:00:00.6628708",
            "data":{
               "message":"Response has been sent to the caller in full"
            }
         }
      ]
   }
}

The trace seems to be wrong. How can the xsl-transform, set-variable and the backend actions run at the exact same time (down to the millisecond)?

inbound:

  1. 2024-06-18T10:43:37.9545915Z - set-variable (DateTime.UtcNow.ToString("o"))
  2. 2024-06-18T10:43:37.9545915Z - set variable (start_time)
  3. 2024-06-18T10:43:37.9701951Z - xsl-transform
  4. 2024-06-18T10:43:37.9701951Z - set-variable (DateTime.UtcNow.ToString("o"))
  5. 2024-06-18T10:43:37.9701951Z - set-variable (end_time)
  6. 2024-06-18T10:43:37.9701951Z - set-backend-service

backend - 2024-06-18T10:43:37.9701951Z

outbound - 2024-06-18T10:43:38.6108878Z

Azure API Management
Azure API Management
An Azure service that provides a hybrid, multi-cloud management platform for APIs.
1,908 questions
0 comments No comments
{count} votes