Usability issues with az monitor activity-log list

[joshua-berry-ntnx]

Describe the bug

I am trying to write a script to pull all activity-log entries going back to a beginning timestamp, regardless of how many entries there are. (This means fetching entries in a loop, since the API limits the number of entries that can be returned at once.) I've spent more time trying to understand the behavior of az monitor activity-log list than I have debugging the script itself, because the command-line options seem to be broken and/or ambiguous in a few ways:

1. Specifying --offset sometimes pauses for a really long time, and then returns zero results, even when I know results are there to be found. Querying the same time window with --start-time returns results, however. (This issue is intermittent and I'm not always able to reproduce it, so I'm not actually sure if this is an Azure CLI issue or a back-end service issue.)
2. Specifying --start-time causes entries OLDER than the time specified to be returned, rather than NEWER entries (contrary to what the documentation implies, and contrary to what the word "start" means).
3. And, it turns out, --end-time does the same thing, but somehow returns different (older) entries???
4. Nowhere in the --help documentation does it say that entries are returned in reverse chronological order, which is the opposite of what I would expect and the opposite of how most logging systems usually work on UNIXy operating systems.

Command Name
az monitor activity-log list

To Reproduce:

I wasn't able to repro (1) after seeing it for a while today; --offset suddenly started returning results again.

(2)/(3) are trivially reproducible:

❯ az monitor activity-log list --max-events 5 --start-time 2023-01-29T13:59:56.636141+00:00 |jq -c '.[]|{eventTimestamp}'
{"eventTimestamp":"2023-01-29T19:59:56.586322+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.582215+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.574379+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.312512+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.278495+00:00"}

Note how all the returned event timestamps are older than the timestamp requested.

Even more concerning, however, is what happens when I swap --start-time with --end-time—I still get events older than the timestamp, but this time they seem to be different events with different timestamps (and no, I did not switch subscriptions in between or anything like that; these commands were run consecutively):

❯ az monitor activity-log list --max-events 5 --end-time 2023-01-29T13:59:56.636141+00:00 |jq -c '.[]|{eventTimestamp}'
{"eventTimestamp":"2023-01-29T13:59:56.517164+00:00"}
{"eventTimestamp":"2023-01-29T13:59:56.506204+00:00"}
{"eventTimestamp":"2023-01-29T13:59:56.491555+00:00"}
{"eventTimestamp":"2023-01-29T13:59:56.442120+00:00"}
{"eventTimestamp":"2023-01-29T13:59:56.441386+00:00"}

So at this point, I have no idea how to make sure I've fetched all the events within a particular time window, since I'm not confident Activity Log is actually showing me everything that's in between the first and last returned events.

Expected Behavior

• Use option names that are unambiguous (--newer-than and --older-than instead of --start-time and --end-time, which seem to mean the opposite of what they say)
• --offset should not reverse its behavior depending on whether --start-time or --end-time is specified; these should be two separate options. For example, journalctl on Linux uses --since and --until for these two concepts.
• Sort returned entries oldest-first by default, OR provide an option to sort oldest-first, OR at least make it clear in --help output that entries are sorted newest-first.
• Return all the events in the time window requested, up to the --max-events limit, properly-sorted by timestamp so that I can fetch the next batch of events by narrowing the time window accordingly.

Environment Summary

macOS-13.1-x86_64-i386-64bit, Darwin 22.2.0
Python 3.10.10
Installer: HOMEBREW

azure-cli 2.45.0

Additional Context

[yonzhan]

@AllyW for awareness

[AllyW]

Hi @joshua-berry-ntnx , great practice for all. There are several parts that I can clarify now:

1. for the part 2 you mentioned below, actually all the returned event timestamps are older newer than the timestamp you requested: 2023-01-29T19:59:56 is newer than 2023-01-29T13:59:56.

az monitor activity-log list --max-events 5 --start-time 2023-01-29T13:59:56.636141+00:00 |jq -c '.[]|{eventTimestamp}'
{"eventTimestamp":"2023-01-29T19:59:56.586322+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.582215+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.574379+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.312512+00:00"}
{"eventTimestamp":"2023-01-29T19:59:56.278495+00:00"}

2. for the part 3, it returned older entries than requested end-time, which is as expected.
3. for the help part 4, logging entries returned in reverse chronological order is out of some quick analysis consideration I believe, like, most developers only tracking their machine activities from the most very recent log lines and backwards.

[AllyW]

@joshua-berry-ntnx also, there are some confusions in your tries that I need to explain:

1. the offset parameter is used to mark the requested time window, not the paging-like offset, and its default value is 6h as the docs put:
   a) if start-time stated but not end-time, then end-time = start-time + offset.
   b) if start-time not stated but end-time does, then start-time = end-time - offset.
   c) if neither, then end-time = now; start-time = end-time - offset
2. the max-events is used in cli side for trimming the returned records, whose default value is 50.
3. the most important part about this az monitor activity-log list cmd, which I think is out of your biggest concern is that, it does not have paging functionality now. Azure service returned all the request and qualified log entries and azure cli returns the first max-events entries to users. So my suggestion for pulling all the log entries you want is that, set a reasonable time-window and filter conditions, and put max-events bigger than the estimated returned number of log entries to get all the entries, and then slide the time window from one to another, then I suppose your scripts can be finished as expected.
4. If any other uncertainty, just let me know.

[joshua-berry-ntnx]

Hi @AllyW, thanks for looking into this and thanks for your reply!

1. for the part 2 you mentioned below, actually all the returned event timestamps are older newer than the timestamp you requested: 2023-01-29T19:59:56 is newer than 2023-01-29T13:59:56.

OMG, you are absolutely right. I stared at those timestamps for long enough trying to figure out what was going on that I just completely missed it, and I guess it took a second set of eyes to notice what I missed. I'm sorry for having wasted your time on this one. 😆

2. for the part 3, it returned older entries than requested end-time, which is as expected.

Yes, I agree.

3. for the help part 4, logging entries returned in reverse chronological order is out of some quick analysis consideration I believe, like, most developers only tracking their machine activities from the most very recent log lines and backwards.

Yes, this makes sense. It was just very surprising to me since most logging tools on Linux/UNIX do the reverse. I think it would be helpful to explicitly call this out in the --help output.

In my case, this bit me because I read the --help output, wrote some scripting around it with the assumption that the oldest entry was first, and then wondered why my script was misbehaving.

1. the offset parameter is used to mark the requested time window, not the paging-like offset, and its default value is 6h as the docs put:
   a) if start-time stated but not end-time, then end-time = start-time + offset.
   b) if start-time not stated but end-time does, then start-time = end-time - offset.
   c) if neither, then end-time = now; start-time = end-time - offset

Right, thanks for explaining—I did figure this out from the --help text, so that part was clear, it just took me a minute or two of reading carefully to understand what was happening.

I do think having separate parameters for start + offset and end - offset would make things a little clearer, just from a usability perspective. For example, journalctl uses --since and --until and allows them to take relative timestamps, see: https://www.man7.org/linux/man-pages/man1/journalctl.1.html#FILTERING_OPTIONS

2. the max-events is used in cli side for trimming the returned records, whose default value is 50.

Yup, this made sense and was clear from the documentation.

3. the most important part about this az monitor activity-log list cmd, which I think is out of your biggest concern is that, it does not have paging functionality now. Azure service returned all the request and qualified log entries and azure cli returns the first max-events entries to users. So my suggestion for pulling all the log entries you want is that, set a reasonable time-window and filter conditions, and put max-events bigger than the estimated returned number of log entries to get all the entries, and then slide the time window from one to another, then I suppose your scripts can be finished as expected.

Right, what you are proposing is exactly what I was trying to do, and the issues I faced in implementing this sliding time window are what prompted me to open this ticket. But thanks for explaining—this tells me I was at least on the right track. 😄

I ended up solving my problem in a different way by fetching logs only for specific resources that I was interested in, since it turned out I really only needed the most recent log entries for each resource (I was looking for resources that had failed to delete).

So I'm all good now—it sounds like there's not actually a functional issue here (apart from my inability to read...), but I hope the UX feedback is helpful.

And again, thanks for taking the time to reply!

[joshua-berry-ntnx]

One more subtle usability thing I ran into; not sure if this should be a new ticket (let me know):

When passing a full URI to --resource-id, I also had to specify --subscription with the subscription ID of the resource, even though this is (seemingly) redundant information. Otherwise, the CLI would query for events matching a resource, but it would send the query using the default subscription that was active in the CLI, rather than the subscription holding the resource (as specified in --resource-id).

So it would end up making an API call like this (output from --debug):

urllib3.connectionpool: Starting new HTTPS connection (1): management.azure.com:443
urllib3.connectionpool: https://management.azure.com:443 "GET /subscriptions/<active-subscription>/providers/Microsoft.Insights/eventtypes/management/values?api-version=2015-04-01&$filter=...resourceId%20eq%20%27%2Fsubscriptions%2F<subscription-with-the-resource>%2Fresourcegroups%2F...%27 HTTP/1.1" 200 None

...meaning the GET to Activity Log would be on the wrong subscription, and thus no results would be returned.

So if the user specifies --resource-id, it might be helpful for the CLI to parse out the subscription ID from that resource ID, and use it when querying Activity Log.