It seems to me that despite specifying %x format, the resulting logs contain decimal value. This is especially confusing as the string contains 0x prefix:

[3][840b.8435][01:17:56.211381][strm][0x7ee0ec008c50] Setting flags 0x16 (existing flags: 0x0)

https://github.com/microsoft/msquic/blob/e855aa04835dd31d113bb444c5cb2eb9593c286c/src/core/send.c#L410-L415

https://github.com/microsoft/msquic/blob/e855aa04835dd31d113bb444c5cb2eb9593c286c/src/generated/linux/send.c.clog.h.lttng.h#L4C12-L27

Potentially related: #69

In microsoft/msquic#760 I had to clean build with dev mode to get clog to update properly for some reason. Not sure why, but that shouldn't be required. Seems to indicate something is getting improperly cached.

Starting up a dotnet app takes a non trivial amount of time, and can result in much larger build times if a lot of files are needed to be parsed. By batching files together, this overhead can be minimized.

The decoded logs currently look like the following:

[0][][04:09:46.599785][time][0x5623db075208] Updating Connection 0x7fd550000b20.
[0][][04:09:46.599786][time][0x5623db075208] Next Expiration = {1412964260, 0x7fd550000b20}.
[0][][04:09:46.599787][conn][0x7fd550000b20] Flush complete flags=0x0
[0][][04:09:46.599788][conn][0x7fd550000b20] Scheduling: 0

Notice the extra [] after the [0]. This should be removed.

I was just looking at a log generated from the MsQuic CI and I found this line (for an assert):

[0][][04:09:46.617630][ lib] ASSERT, 421:"/home/vsts/work/1/s/src/platform/platform_linux.c"<SKIPPED:BUG:MISSINGARG:arg4:ANSI_String>.

This maps to the following code:

void
QuicPlatformLogAssert(
    _In_z_ const char* File,
    _In_ int Line,
    _In_z_ const char* Expr
    )
{
    QuicTraceEvent(
        LibraryAssert,
        "[ lib] ASSERT, %u:%s - %s.",
        (uint32_t)Line,
        File,
        Expr);
}

That is triggered by this macro:

#define QUIC_FRE_ASSERT(exp) ((exp) ? (void)0 : (QuicPlatformLogAssert(__FILE__, __LINE__, #exp), quic_bugcheck()));

I don't know why clog would claim the arg is missing. I suspect a CLOG bug. The artifacts can be found here (for now): https://dev.azure.com/ms/msquic/_build/results?buildId=99107&view=artifacts&type=publishedArtifacts

If the decoder file has changed, we should mark the sidecar as dirty.

When looking through the code to collect msquic events created by clog, I noticed this:

lttng enable-event --userspace CLOG_*

I don't want CLOG in my event name. I should be able to choose a prefix (QUIC_ or MSQUIC_ for instance) and not be cluttered by CLOG.

It's quite common for data included in logs to be considered PII when deployed in production (e.g. Client IP addresses). It would be great if we could use CLOG to tackle this problem. To support this, I think we'd need the following changes to CLOG:

• A way to annotate individual parameters as possible PII.
• A way to configure a custom runtime PII "switch" that CLOG would use to trigger the PII or cleartext version of an event.
• For events with PII parameters, CLOG generates a different event macro that checks the PII switch. If true the macro hashes (or something equivalent) the PII data before passing it down to the relevant trace module.

P.S. Is there such thing as a PII event independent of the parameters? I can't think of a case.

I just pushed a PR in MsQuic: microsoft/msquic#677. It appends to an existing event. I ran the build on Linux with the dev mode ENV set and clog only updated the hash, not the event definition.

Warning: Contentious Issue Ahead

For every argument for an event, clog tracks the following:

 {
  "VariableInfo": {
  "UserSpecifiedUnModified": "\r\n            CLOG_BYTEARRAY(sizeof(Connection->PeerTransportParams.PreferredAddress), &Connection->PeerTransportParams.PreferredAddress)",
  "UserSuppliedTrimmed": "CLOG_BYTEARRAY(sizeof(Connection->PeerTransportParams.PreferredAddress), &Connection->PeerTransportParams.PreferredAddress)",
  "SuggestedTelemetryName": "arg3"
  },
  "DefinationEncoding": "!SOCKADDR!",
  "MacroVariableName": "arg3"
}

It does this (as I understand) to prevent any kind of change. I prefer that (and argue for) clog completely ignore the format of the parameters passed into the event. Allow the code to change this at will. This will help development burden and significantly reduce the overhead of the side car. For the event the above example was taken from, removing this would result in a 27% line count reduction.

Going even further, if you remove this as suggested, I believe it might be worth removing the splitArgs all together, as they don't seem to add anything that can't be easily calculated from the TraceString already.

FYI, the full event payload:

"PeerPreferredAddress": {
  "ModuleProperites": {},
  "TraceString": "[conn][%p] Peer configured preferred address %!SOCKADDR!",
  "UniqueId": "PeerPreferredAddress",
  "splitArgs": [
	{
	  "VariableInfo": {
		"UserSpecifiedUnModified": "\r\n            Connection",
		"UserSuppliedTrimmed": "Connection",
		"SuggestedTelemetryName": "arg1"
	  },
	  "DefinationEncoding": "p",
	  "MacroVariableName": "arg1"
	},
	{
	  "VariableInfo": {
		"UserSpecifiedUnModified": "\r\n            CLOG_BYTEARRAY(sizeof(Connection->PeerTransportParams.PreferredAddress), &Connection->PeerTransportParams.PreferredAddress)",
		"UserSuppliedTrimmed": "CLOG_BYTEARRAY(sizeof(Connection->PeerTransportParams.PreferredAddress), &Connection->PeerTransportParams.PreferredAddress)",
		"SuggestedTelemetryName": "arg3"
	  },
	  "DefinationEncoding": "!SOCKADDR!",
	  "MacroVariableName": "arg3"
	}
  ],
  "macro": {
	"MacroName": "QuicTraceLogConnInfo",
	"EncodedPrefix": "[conn][%p] ",
	"EncodedArgNumber": 2,
	"MacroConfiguration": {
	  "linux": "lttng_plus",
	  "stubs": "stubs",
	  "windows_kernel": "empty",
	  "windows": "empty"
	},
	"CustomSettings": null
  }
}

From the latest (v0.1.6.0) logs, it looks like clog is going quote-happy:

  35 [1][][02:36:05.929076][test] START "QuicTestClientDisconnect"
  70 [1][][02:36:05.929215][test]---> "NewPingConnection"
  76 [1][][02:36:05.929309][test]<--- "NewPingConnection"
  79 [1][][02:36:05.929336][test]---> "SendPingBurst"
 100 [1][][02:36:05.929428][test]<--- "SendPingBurst"
 172 [1][][02:36:05.937024][test]---> "ConnectionAcceptAndIgnoreStream"
 173 [1][][02:36:05.937026][test]<--- "ConnectionAcceptAndIgnoreStream"
2822 [1][][02:36:05.963086][ lib] ERROR, 0, "EVP_DecryptFinal_ex failed".
2833 [1][][02:36:05.963136][test]---> "PingStreamShutdown"
2835 [1][][02:36:05.963140][test]<--- "PingStreamShutdown"
2840 [1][][02:36:05.963199][ lib] ASSERT, 421:"/home/vsts/work/1/s/src/platform/platform_linux.c"<SKIPPED:BUG:MISSINGARG:arg4:ANSI_String>.

Let's remove all those.

Currently, clog is missing quite a bit of the printf format specification. It should have complete inbox support (no custom stuff necessary). We need to get that working before we can really claim it to be "using printf() style" events. IMO, this is the best documentation of the format: http://www.cplusplus.com/reference/cstdio/printf/

Every single event in the sidecar duplicates the exact same macro payload. This is unnecessary and results in a significant bloat in the file. Practically, it looks like the simplest solution is to just embed the full config (including dependents) into the sidecar.

For example, in msquic, we have 12 different macro definitions right now; and those are duplicated 506 times in the sidecar. That's a 42x increase!

CLOG Unique ID's must be alpha numeric and // LibraryErrorStatus is not

Right now, if there is a compile error in the decode scripts, it's not discovered until someone actually tries to decode logs. It should be found at build time.

Right now, there's a single stage to build clog and then the example, and it all runs on Ubuntu. Let's make building clog a separate stage (Ubuntu is still fine), it publish build artifacts for everything, and then we run the cmake builds in separate stages for each supported platform, ideally Ubuntu, Linux and macOS.

Rather then requiring defaults.clog_config, defaults.clog.cs and clog.h to be available in a users repo, instead these should be embedded resources in the dll.

For the config files, if nothing is specified from the command line, the embedded copies should be used. If an external file is passed in from the command like, a special path /EMBEDDEDRESOURCE/... would be used we want to load the specified file from an embedded resource.

For clog.h, I can think of 2 choices. One would be have a separate command line flag that would extract it into a specified directory. Running clog specifically to extract that file isn't a big issue, and could easily be done. The other option would be to always extract it to the same directory we generate the headers into, and do that every time. Theres some versioning advantages to that. A 3rd option is just just insert the contents of clog.h into each header. This would make it so you couldn't include 2 logging headers in the same TU, but I'm not sure if thats a problem.

Right now, here's an example of the decoded logs:

[0][][04:09:46.599830][strm][0x5623db187ea0] SF:16 FC:83705 QS:456734 MAX:36394 UNA:18169 NXT:36394 RECOV:0-0
[0][][04:09:46.599831][strm][0x5623db187ea0]   unACKed: [18169, 36394]
[1][][04:09:46.599832][ udp][0x5623db0aede0] Recv 1252 bytes (segment=1252) Src=IPV4:16777343:48559 Dst=IPV4:16777343:32437
[0][][04:09:46.599833][67][84X][31] SH DestCid:"d9cf9e0323943186" KP:0 SB:0 (Payload 1227 bytes)
[1][][04:09:46.599833][conn][0x7fd550000b20] Queuing 1 UDP datagrams
[0][][04:09:46.599834][67][84X][31]   STREAM ID:2 Offset:35179 Len:1215
[1][][04:09:46.599834][conn][0x7fd550000b20] Scheduling: 1
[0][][04:09:46.599848][wrkr][0x5623db0751f8] IsActive = 1, Arg = 1

Currently, only MsQuic logs are being collected, but eventually we might collect multiple providers/filters of logs in parallel. In order to better differentiate providers, we should include the name in the event, such as:

[1][][04:09:46.599833][msquic][conn][0x7fd550000b20] Queuing 1 UDP datagrams

I just updated a version of a dependency in #107 and I was looking at how to update the CLOG version, but I couldn't figure it out. How do we make a new version so that we can say all versions before that shouldn't be used?

dotnet is a big hurdle right now. Eventually, it might be a good idea to rewrite clog in a lower level language (C/C++?) that removes the dotnet requirement.

inline
void
QuicTraceEventStubVarArgs(
    _In_ const void* Fmt,
    ...
    )
{
    UNREFERENCED_PARAMETER(Fmt);
}
#define QuicTraceEvent(Name, ...) QuicTraceEventStubVarArgs("", __VA_ARGS__)

In msquic, we use the following trick to make sure the compiler sees all logs as referenced, rather then just defining away the macro.

  Unhandled exception. System.Collections.Generic.KeyNotFoundException: The given key 'windows' was not present in the dictionary.
     at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
     at clogutils.CLogFileProcessor.ConvertFile(CLogConfigurationFile configFile, ICLogFullyDecodedLineCallbackInterface callbacks, String contents, String contentsFileName, Boolean conversionMode) in /home/vsts/work/1/s/clogutils/CLogFileProcessor.cs:line 310
     at clog.clog.<>c.<Main>b__1_0(CommandLineArguments options) in /home/vsts/work/1/s/clog/clog.cs:line 94
     at CommandLine.ParserResultExtensions.MapResult[TSource,TResult](ParserResult`1 result, Func`2 parsedFunc, Func`2 notParsedFunc)
     at clog.clog.Main(String[] args) in /home/vsts/work/1/s/clog/clog.cs:line 85

Caused by passing windows config profile with a source macro not having a windows key.

It's probably a good idea to onboard a container (pi?) AZP build to the CI for regression checks.

The above change resulted when I ran clog in development mode to update the sidecar. Apparently my newlines are different from machine that originally created the sidecar.

CLOG should trim all whitespace.

By dynamically loading a tracepoint provider, we can solve the multiple linker errors we've been having to work around in msquic. To do this, in the generated headers, after declaring the tracepoint provider, add the following

#undef TRACEPOINT_PROBE_DYNAMIC_LINKAGE
#define TRACEPOINT_PROBE_DYNAMIC_LINKAGE

#ifdef BUILDING_TRACEPOINT_PROVIDER
#define TRACEPOINT_CREATE_PROBES
#else
#define TRACEPOINT_DEFINE
#endif

We would want this to be configurable for each target, as our executable targets we would be fine with a statically linked provider.

Hi,
I point out the lack of some explicit NULL checks in the initialization method Init() of the ETWOutputModule.
I have the simple change ready but I don't have the possibility to publish a branch to proceed with the PR.

On linux, clog outputs 3 files.

file.clog.h
buildname.clog_file.clog.h.c
file.clog.h.lttng.h

The last file is not actually declared as an output in cmake. This causes the build to be ran incorrectly, as the dependencies are not tracked correctly.