stack_info Doesn't include stack info when sending to Seq Server

[Vacant0mens]

• PySeq version: 0.3.20
• Python version: 3.10
• Operating System: Windows

Description

adding stack_info=True doesn't add a stack trace or anything to the REST request body (using StructuredLogger), but it does in the ConsoleStructuredLogger (which, as we know, only writes to console).

What I Did

Added a custom class over seqlog.StructuredLogger and created a custom makeRecord function. (this worked, but didn't add it to the Exception field.)

    def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None):
        if extra and 'log_props' in extra and sinfo != None:
            extra['log_props']['x_Stack'] = sinfo
        return super().makeRecord(name, level, fn, lno, msg, args, exc_info, func, extra, sinfo)

I attempted to create a custom StructuredLogHandler class with a custom _build_event_data function that called event_data = super()._build_event_data() and then added stack information to the Exception field (using seqlog.StructuredLogger.findCaller()), but the Seq server responded with a 500:

{
"@t":"2023-01-02T23:07:12.5629193Z",
"@mt":"HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms",
"@r":["17.8478"],
"@l":"Error",
"@x":"System.ArgumentNullException: Value cannot be null. (Parameter 'evt')
at Seq.Server.Storage.StorageEventNormalizer.FromRawFormat(Object evt, InputSettings inputSettings,
StorageEventCreationData& creationData, Int64& estimatedByteSize, String& error)

... snipped for brevity ...
}

Is there documentation on the REST Api that is more clear about what fields are available for use cases like this?

Pages for Using the REST Api and Server Api Endpoints don't include what body parameters are available nor what is required for each endpoint.

If they did, I would add a commit myself for this issue.

[Vacant0mens]

I was able to add an exception property to the log body using a custom makeRecord function under a custom StructuredLogger class like this:

    def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None, sinfo=None):
        record = super().makeRecord(name, level, fn, lno, msg, args, exc_info, func, extra, sinfo)
        if sinfo and not record.exc_text:
            setattr(record, 'exc_text', sinfo)
        return record

Seems like this could be pretty easily integrated with the main makeRecord function, or even the StructuredLogRecord class's __init___, but I'd rather have this be an open discussion so that it gets put in the right place.

Reasoning:
I did it this way because on like 488 of structured_logging.py (in SeqLogHandler._build_event_data()), it adds event_data['Exception'] = record.exc_text if the record.exc_text is not None, False, or empty string. My custom function is useful, but I think adding another elif for sinfo or stack_info would be a decent place to put it.
Like this:

        if record.exc_text:
            # Rendered exception has already been cached
            event_data["Exception"] = record.exc_text
        elif record.stack_info and not record.exc_info:
            event_data["Exception"] = record.stack_info
        elif isinstance(record.exc_info, tuple):
            # Exception info is present
            event_data["Exception"] = record.exc_text = self.formatter.formatException(record.exc_info)
        elif record.exc_info:
            # Exception info needs to be captured
            exc_info = sys.exc_info()
            if exc_info and exc_info[0] is not None:
                event_data["Exception"] = record.exc_text = self.formatter.formatException(record.exc_info)

        return event_data

[tintoy]

Thanks for the detailed report! I like this idea - will give it a try this weekend 🙂

[tintoy]

Thanks for your patience, and sorry for the delay!

Published v0.3.23 🙂

[Vacant0mens]

I'm seeing this feature add the stack information twice to stdout in all of the following cases:

seqlog.configure_from_dict(config=config_dict) ,
seqlog.configure_from_dict(config=config_dict, support_stack_info=True) ,
seqlog.configure_from_dict(config=config_dict, support_stack_info=False)

The last one is especially curious.

Is this expected? or is there possibly something wrong with my implementation?

[tintoy]

Hmm, no shouldn’t be! Will have a look in my lunch break and see what I can see :)

[Vacant0mens]

I tested it with this code and got the same results; double stack traces.
This is almost as basic as you can get, so I don't think it's my implementation.

import seqlog

class Log(seqlog.StructuredLogger):
    def __init__(self):
        super().__init__(name='Seq')

if __name__ == '__main__':
    logger = Log()
    logger.warning("This is a warning", stack_info=True)

[tintoy]

Do the stack traces sent to Seq also get doubled up?

[Vacant0mens]

Found it!
Looks like the default formatter includes adding both ext_text and stack_info to the stream if you don't specify any formatting or alternate log handlers that use a non-default formatter. (see logger/__init__.py: lines 696-703)
Which makes sense for my other implementation because I was using the ConsoleStructuredLogHandler class (I think), which inherits the default Handler class, which inherits the default Formatter class.

If it helps, here's the call stack that I was seeing when the code hit the default formatter.

format (c:\Python311\Lib\logging\__init__.py:696)
format (c:\Python311\Lib\logging\__init__.py:953)
emit (c:\Python311\Lib\logging\__init__.py:1110)
handle (c:\Python311\Lib\logging\__init__.py:978)
callHandlers (c:\Python311\Lib\logging\__init__.py:1714)
handle (c:\Python311\Lib\logging\__init__.py:1644)
_log (c:\Python311\Lib\logging\__init__.py:1634)
_log (c:\Python311\Lib\site-packages\seqlog\structured_logging.py:215)
warning (c:\Python311\Lib\logging\__init__.py:1501)
<module> (c:\Python311\Lib\site-packages\seqlog\seqlog_test.py:9)

[tintoy]

Nice catch! I'll fix that up shortly :)

[tintoy]

Hmm, so it sounds if exc_text is already populated, and includes the stack trace, then stack_info should not be populated?

Might be a little tricky to work out at runtime (does exc_text contain formatted stack_info), but I can probably add a flag to turn on that heuristic (clear out stack_info if exc_text is already populated) if you think it would be helpful (but will try not to change existing behaviour unless consumers opt into it)...

[Vacant0mens]

So the makeRecord method might not be the best place to have the code copy stack_info into exc_text since lots of stuff happens between there and sending the log to Seq and/or emitting the logs. It seemed to work in my original implementation because I was specifically using only the SeqLogHandler and probably lots of other custom things. Seems like this happens most when the defaults are used.

I think it might be cleaner if (like the second code block of my second comment on Jan 9th) you revised the if/elif statements in the SeqLogHandler._build_event_data() method, just before return event_data (current version has it in structured_logging.py lines 519-532). That way you don't have to worry about other loggers or formatters getting in the way.

[tintoy]

Ok, yes, I think that makes sense to me (sorry, it's been a while since I looked at this code and I'm waiting for the coffee to kick in!).

Effectively, we're just talking about removing the code that caches the exception info in exc_text (i.e. the middle expression from 3-part statement of the form event_data["Exception"] = exc_test = XXXX), right?

[Vacant0mens]

Yes, so I think what you have in SeqLogHandler._build_event_data() right now should do exactly what we need without your update to StructuredLogger.makeRecord().

My modification/override to/of makeRecord() was a workaround that allowed me to do the same thing without updating the seqlog module code. I think my second comment above was a little overly-explained. :/

[tintoy]

Ah, ok - you mean we get rid of:

if sinfo and not record.exc_text:
    setattr(record, 'exc_text', sinfo)

?

[tintoy]

Gotcha! All good, doing it now :)

[Vacant0mens]

Correct. That if/setattr in StructuredLogger.makeRecord() is what's causing the stack info to get added to stdout/lastResort twice, but only because of all the default logger and formatter code. It doesn't seem to be sending double-stack-traces to Seq as far as I can tell.

[tintoy]

Published v0.3.24! 🙂

[Vacant0mens]

stdout/lastResort looks much better with that change! 👍

I'll test it out with a Seq server and some more custom things tomorrow.

[tintoy]

Thanks!

[Vacant0mens]

Looks good! Thanks for pushing that update! :)

[Vacant0mens]

for some reason my logging instance is adding a bunch of \'s to the extra properties. I'm looking into it more, but so far it looks like it's happening somewhere in the _log() function maybe.

{
    "@t":"2023-04-17T12:02:28.7799090-06:00",
    "@mt":"This is critical.",
    "@m":"This is critical.",
    "@i":"83628c4f",
    "@l":"CRITICAL",
    "@x":"NoneType: None",
    "BuildVersion":"\"\\\"\\\\\\\"1.2023-today\\\\\\\"\\\"\"",
    "LoggerName":"\"\\\"\\\\\\\"Seq\\\\\\\"\\\"\"",
    "ThreadId":"\"\\\"42620\\\"\"",
    "ThreadName":"\"\\\"\\\\\\\"MainThread\\\\\\\"\\\"\""
}

It's also not adding the stack information to the logs. :/

[Vacant0mens]

So far it doesn't seem to be the _build_event_data() function. Could be something in the Json encoder in the queue processor.
But since that's happening in the background, I'm not sure how to troublshoot it.

It's also logging everything 3 times. 😮

[tintoy]

Is this what’s going to Seq or what’s being logged elsewhere?

[Vacant0mens]

Yes, that Json is what I get from the seq server when I download the raw log item.

[tintoy]

Hmm, I wonder if this is a regression with the recent changes or something environmental (e.g. Python version)…

[Vacant0mens]

I added some print's to the publish_log_batch() function. looks like it's running that function 3 times in a row, even though there's only one item in the batch. So it's re-serializing it with the json 3 times, which explains the extra \'s.
Might be my implementation.

[Vacant0mens]

oh wow. definitely my implementation. ... I had the handler and logger set up indented one-too-many times and it was included in a for loop, so it was setting up my Seq logger for each time the loop ran (which was 3 times). 🤦

However, it's serializing my extra properties and escaping the double-quotes still. So the record still looks like this:

{
    "@t":"2023-04-17T15:43:52.5697690-06:00",
    "@mt":"This is a warning.",
    "@m":"This is a warning.",
    "@i":"7fb06904",
    "@l":"WARNING",
    "@x": "... snipped...",
    "BuildVersion":"\"1.2023-today\"",
    "Environment":"\"Dev\"",
    "ThreadId":"8176",
    "ThreadName":"\"MainThread\""
}

for some reason it's escaping each extra property string rather than taking them as single strings. Looks like it's getting processed the same way as the stack info.

[Vacant0mens]

looks like it's this line in _build_event_data() that's escaping the double-quotes:
arg = best_effort_json_encode(arg) -- line 498-ish in structured_logging.py.

UPDATE:
Aahh.. I see! ... Each arg is getting submitted to best_effort_json_encode() as a string, and coming back as a json-encoded/escaped string, rather than the json.dumps() call rejecting it because it doesn't have any Json syntax markers (like { or :)

Is that best_effort_json_encode() function even needed since the publish_log_batch() already calls json.dumps(resp, cls=self.json_encoder_class) ? Seems redundant to me.
I tested with commenting out that line in the _build_event_data() under the elif isinstance(record, StructuredLogRecord): section, and it's logging like I'd expect.

UPDATE 2:
within my inherited class (class Seq(seqlog.StructuredLogger)) it looks like calling super().error(msg='text', exc_info=True, stack_info=True) results in "@x": "NoneType: None" even though I see the stack_info and exc_info in the console logs, and super().warning(msg='text', exc_info=False, stack_info=True) includes the stack_info in Seq like I'd expect.

I'm testing this log without any actual exceptions going on in my code, so that's sort of not surprising. If I did, it seems like that would be included. I see both the stack_info and exc_info in the console logs though, which means if there were an exception going on, the stack trace might show up twice in the console.

Could you add a check near the end of _build_event_data() to check if there's already an exception happening somewhere, and if not, just include the stack info instead?

[Vacant0mens]

This might just be another implementation thing...

StructuredLogger.error(msg='text', exc_info=True, stack_info=True) <- includes None Type: None and the value of stack_info in console, but only None Type: None in Seq.

Seems like I should either include exc_info=True OR stack_info=True, but I should probably not use both. Is that right? or is this going to need a little more work?

[tintoy]

@Vacant0mens - whatever the issue is, it seems to be affecting other users too; I’m going to roll back that last change (the one that fixed the console logging issue) in the published package (just for now) while we figure out what’s going on.

[Vacant0mens]

Okay. Thanks for rolling back. Sorry for the issues.

• I've confirmed the escaped/added quotes are because of the arg = best_effort_json_encode(arg) call on line 498-ish in structured_logging.py, but I'm not familiar enough with the lower levels of the json module to know what to do with that.

• Other side work: I added some logic to the end of _build_event_data() to add the stack info if exc_info[0] == None.

Feel free to modify/update this code as needed to make it work better than my crude tests.

        if record.exc_text:
            # Rendered exception has already been cached
            event_data["Exception"] = record.exc_text
        elif self._support_stack_info and record.stack_info and not record.exc_info:
            # Feature flag is set: fall back to stack_info (sinfo) if exc_info is not present
            event_data["Exception"] = record.stack_info
        elif isinstance(record.exc_info, tuple):
            # Exception info is present
+            if record.exc_info[0] is None and self._support_stack_info and record.stack_info:
+                event_data["Exception"] = "{0}--NoExeption\n{1}".format(seqlog.logging.getLevelName(record.levelno), record.stack_info)
+            else:
+                event_data["Exception"] = record.exc_text = self.formatter.formatException(record.exc_info)
-            event_data["Exception"] = record.exc_text = self.formatter.formatException(record.exc_info)
        elif record.exc_info:
            # Exception info needs to be captured
            exc_info = sys.exc_info()
            if exc_info and exc_info[0] is not None:
                event_data["Exception"] = record.exc_text = self.formatter.formatException(record.exc_info)

        return event_data

You'd need to be careful not to use exc_info=True and stack_info=True at the same time (otherwise you'd see a double-stack-trace in the logs). As far as I can tell, those two settings aren't mutually exclusive, so this seems to be similar functionality to the main logging module that seqlog is based on. If I'm wrong, the above code can be ignored. 👍

[tintoy]

Nice work! 🙂

[tintoy]

@Vacant0mens - I think this is probably sufficient to fix the problem (regardless of any other behavioural changes):

def best_effort_json_encode(arg):
    # No encoding necessary for strings.
    if isinstance(arg, str):
        return arg

    try:
        return json.dumps(arg)
    except TypeError:
        try:
            return str(arg)
        except TypeError:
            try:
                return repr(arg)
            except TypeError:
                return '<type %s>' % (type(arg), )
    except ReferenceError:
        return '<gone weak reference>'

What do you reckon?

[tintoy]

Published v0.3.26.

It seems to work as far as I've been able to test it, but I don't have access to my old Seq instance so have had to rely on somewhat more theoretical testing than usual 🙂

[Vacant0mens]

yeah, as long as the end-goal of this method is to always return a string, this would be fine. 👍

[Vacant0mens]

Has any more testing been done on that version?

If not, I can test it a bit. Otherwise, can this issue be closed?

[tintoy]

I'd appreciate it if you could try it out and see if it works for your use-case; if it works for you I'd be happy to close this issue 🙂

Thanks!

[Vacant0mens]

yep. I'm able to log stack trace info with the stack_info=True argument, even in warning logs.
Except that it's adding the stack info twice in the console, but not to the Seq server.
Might be my implementation. I'll test a little more.

[Vacant0mens]

looks like the default logging.Formatter class's format() function has separate checks for exc_text and stack_info when it formats the message, so it'll append the stack_info after it's already appended the exc_text to the message/record. It's an elegant function, but it doesn't account for exc_text having a value at the same time as stack_info. Probably could use a revision.

From logging.__init__.py (logging module as of today, lines 674-704):

    def format(self, record):
        """
        Format the specified record as text.

        The record's attribute dictionary is used as the operand to a
        string formatting operation which yields the returned string.
        Before formatting the dictionary, a couple of preparatory steps
        are carried out. The message attribute of the record is computed
        using LogRecord.getMessage(). If the formatting string uses the
        time (as determined by a call to usesTime(), formatTime() is
        called to format the event time. If there is exception information,
        it is formatted using formatException() and appended to the message.
        """
        record.message = record.getMessage()
        if self.usesTime():
            record.asctime = self.formatTime(record, self.datefmt)
        s = self.formatMessage(record)
        if record.exc_info:
            # Cache the traceback text to avoid converting it multiple times
            # (it's constant anyway)
            if not record.exc_text:
                record.exc_text = self.formatException(record.exc_info)
        if record.exc_text:
            if s[-1:] != "\n":
                s = s + "\n"
            s = s + record.exc_text
        if record.stack_info:
            if s[-1:] != "\n":
                s = s + "\n"
            s = s + self.formatStack(record.stack_info)
        return s

I added a couple lines to the beginning of ConsoleStructuredLogHandler's emit() function before msg = self.format(record):

    def emit(self, record):
        if record.exc_text and not record.exc_info:
            record.exc_text = ''
        msg = self.format(record)

        print(msg)
        if hasattr(record, 'kwargs'):
            print("\tLog entry properties: {}".format(repr(record.kwargs)))

This cleared up the double-stack issue in the console logs, but this might not be the best place for it.

[tintoy]

Good catch!

Happy to take a PR for that or can make the change myself if you prefer :)

[Vacant0mens]

Ah, I think I found why it was logging double stacks to the console.

A change from earlier in structured_logging.StructuredLogger.makeRecord() in v0.3.26 that has since been cleared up:
Lines 239-240:

        if sinfo and not record.exc_text:
            setattr(record, 'exc_text', sinfo)

I'll test with latest master and see if there's anything else.

[Vacant0mens]

Yep. That looks much better. I'll make a PR to clean out those two lines. 👍