Unexplicable error, any thoughts?

[Lisandro]

I've been dealing with this issue since some time now, but can't understand how can it even happen. It shouldn't. But it does :P

In the past I had reported a very similar problem (probably related), but as I was using a very old web2py version, and considering that it was impossible that the problem to happen in the way it was described, I just Iet it go. The thread where we talked about it is this:

https://groups.google.com/forum/#!searchin/web2py/lisandro%7Csort:date/web2py/gdmTww_jrkA/IXzu5Ns3CQAJ

Anyway, now I'm running web2py 2.17.1 and I'm facing a very similar issue. In fact, it happens in the same place of the code of the previous issue, so I think it's the same issue, but I cant' figure out how it can even happen.

This is the traceback:

Traceback (most recent call last):
  File "/var/www/medios/gluon/restricted.py", line 219, in restricted
    exec(ccode, environment)
  File "applications/informatesalta_panel/compiled/controllers.contenido.editar.py", line 727, in <module>
  File "/var/www/medios/gluon/globals.py", line 419, in <lambda>
    self._caller = lambda f: f()
  File "/var/www/medios/gluon/tools.py", line 3982, in f
    return action(*a, **b)
  File "applications/informatesalta_panel/compiled/controllers.contenido.editar.py", line 338, in editar
  File "/var/www/medios/gluon/packages/dal/pydal/objects.py", line 753, in insert
    ret = self._db._adapter.insert(self, row.op_values())
  File "/var/www/medios/gluon/packages/dal/pydal/adapters/base.py", line 486, in insert
    raise e
IntegrityError: inserción o actualización en la tabla «multimedia_contenido» viola la llave foránea «multimedia_contenido_contenido_fkey»
DETAIL:  La llave (contenido)=(176336) no está presente en la tabla «contenido».

It is in spanish, but it's simple: a classic "IntegrityError: insert or update on table violates foreign key constraint".

I have the table "contenido" (spanish for "content"), that is a table for storing articles and news.

I have also another table called "multimedia" which stores media files.

And finally I have the table "multimedia_contenido" that stores the relations between the first two tables (which media is assigned to which article)

The controller/function that allows the user to edit the content and its media files is contenido/editar, that's the place where the error happens.

The first argument of the function contenido/editar is the record ID of the "contenido" table.

This is the code of the function (simplified):

@auth.requires_login()
def editar():
    contenido = db.contenido[request.args(0)]
    if not contenido:
        redirect(URL('default', 'index'))
   
    # if a POST is sent, updates the contenido
    if request.env.request_method == 'POST':
        datos = {
            'last_updated': request.now,
            'title': request.vars.title,
            'detail': request.vars.detail}
        contenido.update_record(**datos)
       
        # in some very weird situations of the past, contenido was None at this
        # point, so I had to add this ugly check:
        if not contenido:
            return response.json({'success': False})
       
        # runs a custom virtual method that only does a simple db.executesql()
        contenido.actualizar_tsv()


        # stores relations to multimedia_contenido
        contenido.multimedia_contenido.delete()
        for id_multimedia in request.vars.multimedia.split(','):
            if db(db.multimedia.id == id_multimedia).count():
                # this is the line producing the error
                db.multimedia_contenido.insert(
                    contenido=contenido.id,
                    multimedia=id_multimedia)

        return response.json({'success': True})

    return dict(contenido=contenido)

Notice the traceback shows that the error is at line db.multimedia_contenido.insert(... and it says that the the ID 176336 is not present in the table contenido. 

But wait!! The detailed error ticket shows that the URL where the error triggered was in fact /contenido/editar/176336

And, if you check the first line of my function, you will notice it gets the "contenido" record from the given ID passed as the first argument of the function.

So, how can it be even possible? 

The post is made to the URL /contenido/editar/176336.

The first thing the function does is to check that the row exists. If it doesn't exist, it redirects. So in theory there is no way it gets to the end of the function if the content doesn't exist.

But the ticket error shows another thing: it says that the code did run almost to the last, when it throwed error because the content didn't exist anymore in the database table.

The only thing I could think off is a problem with transactions/commits.

I'm using PostgreSQL.

I already checked my code and no commit is made between the start and the end of the function.

I'm pretty lost.

Another weird thing is that the error is intermitent. My application is used by several users. They publish about 1.000 articles daily, and the error happens about 4 or 5 times per day. I've tried everything to reproduce the error but I couldn't.

Any thoughts?

[Val K]

It seems that something deletes the record while your controller is runnig. Is there another one that could do it?

[Dave S]

On Friday, November 30, 2018 at 10:54:14 AM UTC-8, Val K wrote:

It seems that something deletes the record while your controller is runnig. Is there another one that could do it?

In addition, examine the locals in each frame as shown in the error ticket.  There might be a hint of clue there.

/dps
 

[Lisandro]

Thank you for your comments. I checked the locals in the detail of the error ticket, and also checked every code/args/vars section, but I didn't find anything interesting.

Val's comment made me think again if something else could delete the record. 

This is a multi-user scenario and, in theory, two users could be trying to edit/delete the same content. 

However, the time it takes to run the function is very low, so the only scenario where the error could happen is if the second process (the one that deletes the record and commits) runs right between the start/end of the first process (the "first process" would be the function that I exposed earlier).

I mean, if that is what is happening, it must be happening in a very specific timeframe. 

Still, I'm skeptical about this explanation, mostly because if that's the reason, the error should happen much less frequently than it does.

My application is running compiled, and I can't decompile it in production.

I guess that I will make a fix to my code and check that the record exists before doing the insert. Not necessarily an elegant solution, but it will avoid the error tickets being created.

Any other comment is very welcome.

Regards,

Lisandro.

[Val K]

Instead just db.table[id] you can use db(db.table.id==...).select(... , for_update=True), it blocks the record from changes by others until transaction end