Do the Callable & http_endpoint annotations have an impact on logging?

[mcmasty]

Hello,

I just starting using LogzIO (cause I saw the package on the installed list and I wanted to integrate a more robust monitoring solution.)

I am using the python logger, with the LogzIO Handler with a dictConfig().

When I log messages at the module level, they ship to LogzIO without issue. However, when I log from inside an @anvil.server.http_endpoint function or an @anvil.server.callable function, the log messages show up in the Anvil App log but don’t get shipped to LogzIO.

Is it possible the code in the annotation is interfering with LogzIO log handler ?

Related code:

---

Log Config Dict:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'local': {
            'format': '%(asctime)s %(message)s',
        },
        'simple': {
          'format': '%(asctime)-15s %(name)-15s %(levelname)-8s: %(message)s'
        },
        'verbose': {
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        },
        'logzioFormat': {
            'format': '{"additional_field": "value"}'
        }      
    },
    'handlers': {
        'console1': {
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
            'stream': 'ext://sys.stdout',
            'level': 'DEBUG'
        },
        'console2': {
            'class': 'logging.StreamHandler',
            'formatter': 'local',
            'stream': 'ext://sys.stdout'
        },
        'logzio': {
            'class': 'logzio.handler.LogzioHandler',
            'level': 'INFO',
            'formatter': 'logzioFormat',
            'token': ' {{fill_with_real_token}}',
            'url': 'https://listener.logz.io:8071'
        }      
    },
  'loggers': {
    '': {  # Root Logger
        'level': 'DEBUG',
        'handlers': ['console1', 'logzio'],
        'propogate': True
   }  
  }
}

---

Server Code Snippets:

logging.config.dictConfig(LOGGING)
root = logging.getLogger()
logger = root


logger.info('APIServerModule INFO Sniff Test ')
logger.warn('APIServerModule WARN Sniff Test ')
logger.error('APIServerModule ERROR Sniff Test ')
logger.exception('APIServerModuleEXCEPTION Sniff Test')



@anvil.server.http_endpoint('/add/:a/:b')
def add_numbers(a, b):
  logger.info("ENTERING: add_numbers")
  
  a = int(a)
  b = int(b)
  return {
    'originals': [a, b],
    'sum': a + b,
  }

---

Recap

When the above code runs, the 4 “Sniff Test” log messages appear in Anvil App Logs AND LogzIO.

However when add_numbers is called (via PostMan, Curl, etc), the ENTERING add_numbers log message only shows up Anvil App Logs, it never appears in LogzIO.

Based on the fact the module level logging works as expected, I am deducing that the issue is

• (a) In the LogzIO Handler …
• (b) Something with the Anvil annotation altering the log config or squashing the network IO or otherwise interfering so Handler cannot execute as expected

Any thoughts ? or suggestion how I might further investigate and resolve this issue ?

Thanks in advance.

Cheers,
Tyler

---

More Data

Screen Shot of Anvil Logs

with my API token obscured. But you can see the APIServerModule Sniff Tes Log and the add_numbers (last entry)

---

However, in LogzIO … “Sniff Test” messages make it, but the add_numbers did not.

[meredydd]

The only thing I can think of: Is your logging library asynchronous? If you’re not running in Persistent Server mode, the process running your server code shuts down as soon as the result has been returned, which might not leave your logging library enough time to transmit its data.

(Suggested test: Turn on the Persistent Server option in the server module dropdown, or insert a sleep() statement after the logging call in your code but before your function returns.)

[mcmasty]

@meredydd,

Good Catch! Just tried the sleep() test with add_numbers and the add_numbers message is now showing up in LogzIO.

I see that Persistent servers is a Business feature, which is a little beyond my budget right now.

I’ll actually poke around the internet. I am hoping that since I am using the python logging framework, with a custom handler provided by LogzIO, there are similar examples of asynchronous logging with things like AWS Lambda Functions or Open Whisk… where the server is short-lived, but similar pattern where messages are queued up and need to be sent before process dies. I’m hopeful I can find a hook to inject some custom code force the LogzIO handler to flush.

You definitely helped confirm the issue, so thanks!

Cheers,
Tyler

[stefano.menci]

Have your tried using a background task to log?
Background tasks are not killed when the request ends.

[mcmasty]

For anyone following along, I ended up creating a decorator to call flush() on all the handlers after the function has completed.

Code is:

import anvil.server
import functools

def handler_flusher(logger):
  def decorator(fn):
      @functools.wraps(fn)
      def wrapper(*args, **kwargs):
          try:
              args_repr = [repr(a) for a in args]
              kwargs_repr = ["{}={}".format(k, v) for k, v in kwargs.items()]
              signature = ", ".join(args_repr + kwargs_repr)
              logger.info('CALLING ' + fn.__name__ + ' ' + signature)
              return fn(*args, **kwargs)
          except Exception:
              logger.exception('call failed')
              raise
          finally:
              logger.info('EXITING ' + fn.__name__)
              print ("Flushing Handlers")
              [h.flush() for h in logger.handlers]
      return wrapper    
  return decorator

---

The re-worked code (using same snippet as higher up this post) now looks like this, where LOGGING is a dictionary (above) with my log config

logging.config.dictConfig(LOGGING)
root = logging.getLogger()
logger = root

@anvil.server.http_endpoint('/add/:a/:b')
@handler_flusher(logger)
def add_numbers(a, b):
  a = int(a)
  b = int(b)
  
  return {
    'originals': [a, b],
    'sum': a + b,
  }

This resulted in log messages in Anvil App Logs, and my LogzIO dashboard. (FYI, my Logz Handler is set to INFO level, which is why I use info in the decorator to verify it flows to Logz.)

[mcmasty]

Update for folks following along with Third-Party Loggers, specifically Logz IO. I am using multiple Anvil Apps to support the Dev / Staging / Production flow, with single Git repository that pushes to multiple remotes.

Due to the fact that only a single anvil.yml can reign supreme at a given time, This creates a challenge for Third-Party Services, like LogzIO in my case. Anyway, I created a little tweak to add the Anvil App Id, to every log message that gets posted to Logzio…

In the logger configuration, you can add the Anvil App Id to every log message

            'format': '{"additional_field": "value", "ANVIL_APP_ID": "%s"}' % str(anvil.app.id)

And it looks like this in LogzIO dashboard

So then it is easy to filter DEV log messages out from PRODUCTION log messages.

It’s not as ideal as having 1 logger per environment, but a decent workaround, if anyone else is using Logz IO

(or any backing service as outlined here Better Secrets management, for Dev / Stage / Prod )