Visual Studio Code – SQLAlchemy not executing update unless walking through code with debugger

I am genuinely baffled by the behavior I’m seeing so I’m hoping someone can shed some light onto what’s going on here. Basically, I have a web app using FastAPI and SQLAlchemy in the back end that involves users posting responses to a survey. In the endpoint accepting the post request for a response, a Response object is created in the database, then a number of Match objects are created in the database with a foreign key to the Response object that was created. During the parsing and creation of the Match objects from the payload, I aggregate a number_correct_matches variable (which is a positive integer) and I then update the Response object to include number_correct_matches via a SQLAlchemy Session in a crud class that has an update function.

The behavior that is baffling me is that when I execute the code that performs this updating operation either when running the full project locally on my raspberry pi 4 where I’m developing (using a local postgresql db) or via a unit test (using an in memory sqlite db), the update in the database does not happen for the Response object. However, there are two scenarios where the update works:

1. If I run the unit test in debug mode in vscode, and step through the for loop in the update function one line at a time, the Response object is updated correctly in the database.

2. If I put a logger statement in the update function and iff the logging statement prints db_object that is being updated, the Response object is updated correctly. If I put a logger statement that does not include db_object, the logger statement is output to the logs, but the object is not updated.

The expected behavior only happens for either of the two above scenarios, otherwise the code is literally skipped (see how below). Additionally, I have other models in the app that utillize the same update function successfully for different attributes (e.g. there is an update endpoint for user objects that uses the same function and I can successfully update a user’s password through it).

I do not understand how the code seemingly only gets executed when directly stepped through in debug mode or when the db_object argument is printed. I know I could just loop through the Match objects in the payload before creating them in the database just to get the number_correct_matches value and create the Response object with that value in the first place, but I really want to understand how it works only when I step through one line at a time or when I have a specific logger statement and not when running the code normally without superfluous logs.

api/response.py

response = crud.response.update(
    session=session,
    db_object=response, # <- this is the already created Response object in the database
    object_in=schemas.ResponseUpdate(
        number_correct_matches=number_correct_matches
    ),
)

schemas/response.py

# properties to receive via API update
class ResponseUpdate(ResponseBase):
    number_correct_matches: int = 0

crud_base.py (extended by crud_response)

def update(
        self,
        session: Session,
        *,
        db_object: ModelType,
        object_in: Union[UpdateSchemaType, Dict[str, Any]]
    ) -> ModelType:
        """
        Updates an object in the database

        Args:
            session (Session): a SQLAlchemy Session object that is connected to the database.
            db_object (ModelType): An object from the database.
            object_in (Union[UpdateSchemaType, Dict[str, Any]]): A pydantic model object used to update the db model object.

        Returns:
            ModelType: The updated db model object.
        """
        # logger.info(f"updating {db_object}") <- with just this logging statement, it works correctly
        logger.info("updating 1")
        # update the db object
        update_data = ( # <- If breakpoint is set here and then I jump to below the for loop without stepping through, it does not work
            object_in
            if isinstance(object_in, dict)
            else object_in.model_dump(exclude_unset=True)
        )
        for field in jsonable_encoder(db_object): # <- It works if breakpoint is set here and then I walk through one line at a time to the end of the for loop
            logger.info("updating 2")
            if field in update_data.keys():
                logger.info("updating 3")
                setattr(db_object, field, update_data[field])
        logger.info("updating 4")
        # update the db object through the session
        session.add(db_object) # <- If breakpoint is set here, it does not work
        session.commit()
        session.refresh(db_object)
        return db_object

The above code when run as is (with the first logger statement commented out) results in the following logs:

2024-07-12 20:53:52.228 | INFO     | app.crud.crud_base:update:82 - updating 1
2024-07-12 20:53:52.229 | INFO     | app.crud.crud_base:update:94 - updating 4

I’ll also add that even though I posted the code in the response endpoint, I also call crud.response.update in conftest.py and I get the exact same behavior.