Logger / Asyncio Can't Find Running Event Loop #232

Saintroi · 2023-10-11T16:54:04Z

Background

Hello! I'm working to implement plombery based on a request I have to run and monitor a python script on a schedule. This particular script is designed to start at 7AM UTC and run for 23 hours. I'm deploying this app to an Azure Web App service.

Because I am importing another python module that actually holds the logic for the task, I've had to get a bit creative to integrate logging with plombery. Simply passing the logger object to the function didn't work well, so I wrote a function to get the name of the logger just after I call get_logger() from plombery. I then pass the name of the logger to the task and have it use logging.getLogger() to retrieve the logger. Unfortunately, it seems this is still resulting in some bugs related to threading. I've included additional information below, please let me know if you need anything else!

Issue

During the task running, I get MOST of my logs coming through correctly, but also have a significant amount of logging errors showing up in the standard output. A full example of one here:

2023-10-11T15:26:51.337065402Z --- Logging error ---
2023-10-11T15:26:51.367307824Z Traceback (most recent call last):
2023-10-11T15:26:51.367567726Z   File "/opt/python/3.11.4/lib/python3.11/logging/handlers.py", line 1498, in emit
2023-10-11T15:26:51.367598426Z     self.enqueue(self.prepare(record))
2023-10-11T15:26:51.367606226Z   File "/home/site/wwwroot/antenv/lib/python3.11/site-packages/plombery/logger/web_socket_handler.py", line 13, in enqueue
2023-10-11T15:26:51.367612026Z     manager.emit(f"logs.{self.run_id}", record.message)
2023-10-11T15:26:51.367629126Z   File "/home/site/wwwroot/antenv/lib/python3.11/site-packages/plombery/websocket/__init__.py", line 58, in emit
2023-10-11T15:26:51.367634926Z     run_all_coroutines(all_coroutines)
2023-10-11T15:26:51.367640426Z   File "/home/site/wwwroot/antenv/lib/python3.11/site-packages/plombery/utils.py", line 13, in run_all_coroutines
2023-10-11T15:26:51.367645826Z     task = asyncio.create_task(coroutine)
2023-10-11T15:26:51.367651026Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-11T15:26:51.367656126Z   File "/opt/python/3.11.4/lib/python3.11/asyncio/tasks.py", line 371, in create_task
2023-10-11T15:26:51.367661226Z     loop = events.get_running_loop()
2023-10-11T15:26:51.367666426Z            ^^^^^^^^^^^^^^^^^^^^^^^^^
2023-10-11T15:26:51.367671526Z RuntimeError: no running event loop
2023-10-11T15:26:51.367676626Z Call stack:
2023-10-11T15:26:51.428225869Z   File "/opt/python/3.11.4/lib/python3.11/threading.py", line 995, in _bootstrap
2023-10-11T15:26:51.428274870Z     self._bootstrap_inner()
2023-10-11T15:26:51.428282670Z   File "/opt/python/3.11.4/lib/python3.11/threading.py", line 1038, in _bootstrap_inner
2023-10-11T15:26:51.428288270Z     self.run()
2023-10-11T15:26:51.428293270Z   File "/opt/python/3.11.4/lib/python3.11/threading.py", line 975, in run
2023-10-11T15:26:51.428298970Z     self._target(*self._args, **self._kwargs)
2023-10-11T15:26:51.428304470Z   File "/opt/python/3.11.4/lib/python3.11/concurrent/futures/thread.py", line 83, in _worker
2023-10-11T15:26:51.428309770Z     work_item.run()
2023-10-11T15:26:51.428314570Z   File "/opt/python/3.11.4/lib/python3.11/concurrent/futures/thread.py", line 58, in run
2023-10-11T15:26:51.428319670Z     result = self.fn(*self.args, **self.kwargs)
2023-10-11T15:26:51.428324770Z   File "/home/site/wwwroot/app.py", line 21, in gtJob
2023-10-11T15:26:51.428359170Z     gt.runSimulation('PUBLISH', loggerName)
2023-10-11T15:26:51.428364870Z   File "/home/site/wwwroot/models/geo/geo.py", line 2442, in runSimulation
2023-10-11T15:26:51.428370270Z     fetch()
2023-10-11T15:26:51.428375770Z   File "/home/site/wwwroot/models/geo/geo.py", line 2314, in fetch
2023-10-11T15:26:51.428380970Z     plom_logger.info('STARTING TO FETCH AT: ' + str(dt.today().strftime("%m/%d/%Y %H:%M:%S")) + '...')
2023-10-11T15:26:51.428386270Z Message: 'STARTING TO FETCH AT: 10/11/2023 15:26:51...'
2023-10-11T15:26:51.428391271Z Arguments: ()
2023-10-11T15:26:51.431878996Z /opt/python/3.11.4/lib/python3.11/logging/handlers.py:1500: RuntimeWarning: coroutine 'WebSocket.send_json' was never awaited
2023-10-11T15:26:51.431901796Z   self.handleError(record)
2023-10-11T15:26:51.431908696Z RuntimeWarning: Enable tracemalloc to get the object allocation traceback

Additional Issue - Maybe Related?

I saw this before updating to the latest version, but it seems it has returned and might be related. Looks to me like it's the error I'd expect if I was trying to get the logger outside of the task run, which I am not.

Side Note: the dark mode log viewer here has a light font color on a light background, so highlighting is necessary to read. Love the addition of dark mode though!

Code

from apscheduler.triggers.cron import CronTrigger

from plombery import task, get_logger, Trigger, register_pipeline, get_app

import models.geo.geo as gt
import logging


def getLoggerName(taskName):
    loggers = list(logging.root.manager.loggerDict.keys())
    matching = sorted([l for l in loggers if str(taskName) in l])
    return matching[-1]

@task
def gtJob():
    logger = get_logger()
    loggerName = getLoggerName("gtJob")

    logger.debug('Starting GT Job')
    gt.runSimulation('PUBLISH', loggerName)
    logger.debug('GT Job Finished')


register_pipeline(
    id="GeoTab",
    description="Run GeoTab Simulation",
    tasks=[gtJob],
    triggers=[
        Trigger(
            id="daily-seven",
            name="Daily7AM",
            description="Run the pipeline every day at 7AM UTC",
            schedule=CronTrigger(hour=7),
        ),
    ],
)

app = get_app();

if __name__ == "__main__":
    import uvicorn
    uvicorn.run('plombery:get_app', reload=True, factory=True)

Web UI Screenshots

The text was updated successfully, but these errors were encountered:

Saintroi · 2023-10-11T21:54:33Z

Update: I wrote this without realizing that v0.4.1 had been released. I'm working on updating and deploying that version to see if any of the above has been resolved.

lucafaggianelli · 2023-10-11T22:26:58Z

hey, thanks for reporting these issues.

About the traceback styling in dark mode and the wrong "no pipelines" message, I fixed them in v0.4.1

About the logging, there were several bugs, especially when using sync tasks (that non-async functions) and I fixed those in 0.4.0 so if your were using v0.3.* that makes sense you faced those issues. Hope you won't get other bugs on the logging 🥶

So if I get correctly, your end goal is to capture logs in plombery that are not generated with the plombery logger... and yes that is a limitation at the moment but I'd like to find a solution as it's a pretty common situation I think, I'll look into it!

Saintroi · 2023-10-12T14:56:44Z

@lucafaggianelli thanks for getting back to me on this!

I can confirm the traceback info box is great now, and the no pipelines message on the front page is gone!

I was using 0.4.0 in the initial post (hence the dark mode) and think the issues I listed are still present in 0.4.1 based on the testing I've done.

The function I'm running is synchronous, so perhaps that does play into the problems I'm experiencing here. I may mess around with running it async, but I cannot make too many changes to the actual process that's being ran here.

The author of the code I'm running included logging, but only using print statements. I think it would be cool if plombery captured any stdout within a task and piped that to the logger somehow.

In the meantime, I've just gone through and added a logger.info call wherever he had print statements, although some modification had to be done since print works differently. The tricky part was getting the logger passed down to his module.

logging.getLogger() was the solution, but in order to get the correct logger I needed the name. Currently I'm just looking at all of the loggers in the Logger dictionary and getting the newest one with the name of my task. Then I pass that name down and call getLogger(plomLoggerName) inside of his module so I can use it.

I think adding a getName function on your custom logging instance would be nice and make that a bit easier.

I'm interested to hear your thoughts around the async / sync stuff since you've been trying to address that. I'm gonna mess around with it on my end a bit and see what happens. If nothing helps then I'm likely going to be opening up another issue momentarily as I'm having issues with this job not running properly on the schedule, but a manual run seems to work fine.

Saintroi · 2023-10-12T19:21:21Z

Based on this line in the error: /opt/python/3.11.4/lib/python3.11/logging/handlers.py:1500: RuntimeWarning: coroutine 'WebSocket.send_json' was never awaited and the traceback, I did some looking around in the plombery source code.

You're probably aware of this, given that you built it, but it seems this is related to this old issue on the FastAPI side: tiangolo/fastapi#98

Based on the code in the files below and reading through that issue (and others) I think you've done this correctly, just not sure why issues are still occurring - other than it's probably something to do with the fact that I'm trying to run synchronous code, which might be blocking some of this from running periodically.

I mostly wanted to post this comment as a summary of what I think is happening, but also to provide some context on my deployment. I am developing on Windows but deploying to a Linux Web App on Azure.

Startup Command: gunicorn -w 4 -k uvicorn.workers.UvicornWorker app:app

Folder structure:

plombery/src/plombery/api/__init__.py

Lines 1 to 21 in 88e72a6

    
           from fastapi import FastAPI 
        
           from plombery.api.authentication import init_auth 
        
           from plombery._version import __version__ 
        
           from .middlewares import SPAStaticFiles, setup_cors 
        
           from .routers import pipelines, runs, websocket 
        
           API_PREFIX = "/api" 
        
           app = FastAPI(title="Plombery", version=__version__, redirect_slashes=False) 
        
           setup_cors(app) 
        
           auth_router = init_auth(app) 
        
           app.include_router(pipelines.router, prefix=API_PREFIX) 
        
           app.include_router(runs.router, prefix=API_PREFIX) 
        
           app.include_router(auth_router, prefix=API_PREFIX) 
        
           app.include_router(websocket.router, prefix=API_PREFIX) 
        
           app.mount("/", SPAStaticFiles(api_prefix=API_PREFIX))

plombery/src/plombery/websocket/__init__.py

Lines 75 to 88 in 88e72a6

    
           async def handle_messages(self, websocket: WebSocket): 
        
               data: dict = await websocket.receive_json() 
        
               msg_type = data.get("type", None) 
        
               payload = data.get("data", None) 
        
               if msg_type == "subscribe": 
        
                   if payload: 
        
                       manager.subscribe(websocket, payload) 
        
               elif msg_type == "unsubscribe": 
        
                   if payload: 
        
                       manager.unsubscribe(websocket, payload) 
        
               else: 
        
                   logger.warning("Unknown message type %s", msg_type)

plombery/src/plombery/api/routers/websocket.py

Lines 1 to 16 in 88e72a6

    
           from fastapi import APIRouter, WebSocket, WebSocketDisconnect 
        
           from plombery.websocket import manager 
        
           router = APIRouter(prefix="/ws") 
        
           @router.websocket("/") 
        
           async def websocket_endpoint(websocket: WebSocket): 
        
               await manager.connect(websocket) 
        
               try: 
        
                   while True: 
        
                       await manager.handle_messages(websocket) 
        
               except WebSocketDisconnect: 
        
                   manager.disconnect(websocket)

lucafaggianelli · 2023-10-20T10:06:51Z

Hey thanks for the detailed debug, I'll take a look asap.

Saintroi · 2023-10-23T13:57:51Z

Update: the creator of the script I'm running made some changes to fix some bugs in his logic, and I altered my startup command to fix another issue that I opened and closed here, and it seems that as a result of those actions, this issue is also gone. I am no longer seeing these messages in the logs.

New startup command: gunicorn --threads 4 -k uvicorn.workers.UvicornWorker app:app

lucafaggianelli · 2023-10-30T17:56:01Z

Did you try to run uvicorn directly, without passing from gunicorn? I'm wondering if the WSGI nature of gunicorn, even though you're using the UvicornWorker, may lead to your issues.

Anyway happy that you solved the problem! In general, sync tasks should work in plombery, but apparently there is still something which I didn't test properly, I'll try to improve the sync testing!

PS: I'm closing this issue as you solved it, though if you need, you can reopen it

Saintroi · 2023-10-30T18:43:36Z

I didn't mess around with using uvicorn in production mostly because the Azure Web App service documentation on this was centered on gunicorn and I'm not really familiar with either of them personally.

That said, I did use uvicorn while testing locally and experienced the same issues, it just seemed to be less frequent. And none of this was happening before I implemented the logging stuff, so I think perhaps there's something weird with sync tasks and logging? Who knows. If anyone else experiences the same thing, feel free to @ me and we can compare and see if we can find the disconnect.

All good for now though, thank you!

morpheus65535 · 2023-11-21T03:49:27Z

@lucafaggianelli I'm getting the same issue since I started using get_logger():

Traceback (most recent call last):
  File "/usr/local/Cellar/python@3.11/3.11.6/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/handlers.py", line 1498, in emit
    self.enqueue(self.prepare(record))
  File "/Users/morpheus/Desktop/bazarr_provider/venv/lib/python3.11/site-packages/plombery/logger/web_socket_handler.py", line 13, in enqueue
    manager.emit(f"logs.{self.run_id}", record.message)
  File "/Users/morpheus/Desktop/bazarr_provider/venv/lib/python3.11/site-packages/plombery/websocket/__init__.py", line 58, in emit
    run_all_coroutines(all_coroutines)
  File "/Users/morpheus/Desktop/bazarr_provider/venv/lib/python3.11/site-packages/plombery/utils.py", line 13, in run_all_coroutines
    task = asyncio.create_task(coroutine)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/Cellar/python@3.11/3.11.6/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py", line 381, in create_task
    loop = events.get_running_loop()
           ^^^^^^^^^^^^^^^^^^^^^^^^^
RuntimeError: no running event loop

Anything I should look for?

Thanks by the way for that great piece of software you made!

lucafaggianelli added bug Something isn't working cat:Backend labels Oct 11, 2023

lucafaggianelli closed this as completed Oct 30, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logger / Asyncio Can't Find Running Event Loop #232

Logger / Asyncio Can't Find Running Event Loop #232

Saintroi commented Oct 11, 2023 •

edited

Saintroi commented Oct 11, 2023

lucafaggianelli commented Oct 11, 2023

Saintroi commented Oct 12, 2023

Saintroi commented Oct 12, 2023

lucafaggianelli commented Oct 20, 2023

Saintroi commented Oct 23, 2023

lucafaggianelli commented Oct 30, 2023

Saintroi commented Oct 30, 2023

morpheus65535 commented Nov 21, 2023

Logger / Asyncio Can't Find Running Event Loop #232

Logger / Asyncio Can't Find Running Event Loop #232

Comments

Saintroi commented Oct 11, 2023 • edited

Background

Issue

Additional Issue - Maybe Related?

Code

Web UI Screenshots

Saintroi commented Oct 11, 2023

lucafaggianelli commented Oct 11, 2023

Saintroi commented Oct 12, 2023

Saintroi commented Oct 12, 2023

lucafaggianelli commented Oct 20, 2023

Saintroi commented Oct 23, 2023

lucafaggianelli commented Oct 30, 2023

Saintroi commented Oct 30, 2023

morpheus65535 commented Nov 21, 2023

Saintroi commented Oct 11, 2023 •

edited