[nightly] Crash on start: app.logger.commit() AttributeError: 'NoneType' object has no attribute 'commit'

delete the cache.db under ./cache/gajim

not sure why this happens we did a database migration and cleared the table

After rm .cache/gajim/cache.db and then even rm -r .cache/gajim behaviour did not change.

$ gajim
No translations found
Dirs searched: [PosixPath('/usr/share/gnome'), PosixPath('/usr/share/cinnamon'), PosixPath('/home/crosser/.local/share/flatpak/exports/share'), PosixPath('/var/lib/flatpak/exports/share'), PosixPath('/usr/local/share'), PosixPath('/usr/share'), PosixPath('/var/lib/snapd/desktop')]
creating /home/crosser/.cache/gajim directory
creating /home/crosser/.cache/gajim/plugins_download directory
creating /home/crosser/.cache/gajim/avatars directory
creating /home/crosser/.cache/gajim/bob directory
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/gajim/application.py", line 201, in _startup
    app.logger = logger.Logger()
  File "/usr/lib/python3/dist-packages/gajim/common/logger.py", line 195, in __init__
    self._load_caps_data()
  File "/usr/lib/python3/dist-packages/gajim/common/logger.py", line 143, in func_wrapper
    result = func(self, *args, **kwargs)
  File "/usr/lib/python3/dist-packages/gajim/common/logger.py", line 1053, in _load_caps_data
    rows = self._con.execute(
  File "/usr/lib/python3/dist-packages/gajim/common/logger.py", line 152, in _convert_disco_info
    return parse_disco_info(Iq(node=disco_info))
  File "/usr/lib/python3/dist-packages/nbxmpp/protocol.py", line 1553, in __init__
    Protocol.__init__(self,
  File "/usr/lib/python3/dist-packages/nbxmpp/protocol.py", line 977, in __init__
    Node.__init__(self, tag=name, attrs=attrs, payload=payload, node=node)
  File "/usr/lib/python3/dist-packages/nbxmpp/simplexml.py", line 109, in __init__
    node = NodeBuilder(node, self)
  File "/usr/lib/python3/dist-packages/nbxmpp/simplexml.py", line 672, in __init__
    self._parser.Parse(data, finished)
xml.parsers.expat.ExpatError: not well-formed (invalid token): line 1, column 0
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/gajim/application.py", line 235, in _activate
    self.interface = Interface()
  File "/usr/lib/python3/dist-packages/gajim/gui_interface.py", line 2068, in __init__
    app.logger.reset_shown_unread_messages()
AttributeError: 'NoneType' object has no attribute 'reset_shown_unread_messages'
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/gajim/application.py", line 310, in do_shutdown
    app.logger.commit()
AttributeError: 'NoneType' object has no attribute 'commit'

hm are you sure you are on git HEAD of Gajim and nbxmpp

I am not, I am on default-nightly:

$ dpkg --list|egrep 'gajim|nbxmpp'
ii  gajim-default-nightly                      20200421-1                                    all          XMPP client written in Python / GTK
ii  python3-nbxmpp-nightly                     20200420-1                                    all          Non blocking XMPP Python library

hm i really don't understand this, i cannot reproduce it although it should be easy.

can you open the cache.db and look into the caps_cache table, there is a data column, normally there should be a valid xml stanza in there.

Do you see something weird?

Can you tell me what plugins you have installed?

Apparently the problems is not in the cache.db: I checked all the tables and they are all empty.

$ sqlite3 .cache/gajim/cache.db "select name from sqlite_master where type='table'"|while read t; do sqlite3 .cache/gajim/cache.db "select '$t', count(*) from $t"; done 
transports_cache|0
caps_cache|0
last_seen_disco_info|0
roster_entry|0
roster_group|0
muc_avatars|0

Looks like it is trying to do something with disco_info? I ran it with -v and I am attaching the result.

gajim-crash-verbose.txt

hm seems impossibe, it tries to convert something it reads from the database,

could you try and put print statements in gajim/common/logger.py

line 151 in _convert_disco_info()

added needs info label

The value of the argument (disco_info) looks like random junk:

b'\x1f\x8b\x08\x00\xef\xf1L[\x02\xff\x8d\x93\xc1R\xc3 \x10\x86\xf3.=:m\xec\x95\x9b\x07={\xf0\x05\x16\xd8\xa4[\x03\x8b\xb0I\xda\xb7\x97T[3VI.Lv\xbfo\xe0g\x87\x98\x8e\xd0K\x15LU\xbd\x92m\xc9W/\xcfOo\xd5A$\xa8\xba>\x82\xd6\x18w\x1c\xdb:D\x166\xdc\xd5\xfa,\x98$"\xb8T\xd2\x0c\x842?\x80$\x81\xbcW\xc9\xb2\x94\x0co\xc87\xbc\xc2\x12,G"\xadK\xd81\xdb%\xfe\xe0Y\xa89\x17\xb5\xde,\xe0M\x9f0\x96\x1cO\xe6}\x89\xafH\x92\xa8L\xa7\xef\x86:\xac\xa7e+\x11|j\xca\xc1\xa4\xf7\xb8\xc4W\x04;\x1d\xc4u[rWg\x1c\xc7]\xcb\xdcv\xb83\xec\xea\x93\x0ba\xfe\x90\x1cF\xa8\x87\xfd*;aJ\xc4~\x95;\x90E^\xbb\xf1\xc0dp\x92\xbf.\xa4\xe8Cu\x90dV2\xebY5`\xbc\x04\xf9\xee\x9c\x94a\x9f\xa7\x8b\xde`\xd5G\xaf\xa6\xdd\x15\x88\xe4\xbf/k\xeaq\xd6\x1c@ *\x9b\xd7\xbb\xa6C\x81"\xb8N\xff\xc6uNu+\x8e\xe4\xf3\xed\xd4\xfe\xae\x03!$\x15\xf3\x14\n\x08zK\xfc?\xbeL\xf3\x0e_^U\xe0(I\xe5\xf9m{\xfb\xd7\x113)\xc2\xf8[\nY\xfa\xa9\x84\x1c~\x02\xa4a\xeb\xd1\xb5\x04\x00\x00'

but is it a good reason to crash?

Where is supposed to come from, I could check it.

Missed this question, sorry:

Can you tell me what plugins you have installed?

$ ls -l .local/share/gajim/plugins
total 16
drwxr-xr-x 4 crosser crosser 4096 Jan 23 14:57 clients_icons
drwxr-xr-x 6 crosser crosser 4096 Apr  5 22:48 omemo
drwxr-xr-x 3 crosser crosser 4096 Mar 17 08:49 plugin_installer
drwxr-xr-x 3 crosser crosser 4096 Mar 21 10:43 url_image_preview

can you disable the client icons plugin, delete the cache and try again please

this somehow is counter to what you showed, if there are 0 rows in the database, what is it loading here..

I moved all plugins one by one away from .local/share/gajim/plugins and it did not change behaviour. Then, because I realized that the failing code was called from sqlite, I looked what databases are present there. And the only one other than keys of (already disabled) omemo, there was logs.db

So once I moved away logs.db, gajim started normally. But of course history is empty.

Speaking about client_icons, it indeed throws exception, but that does not prevent gajim from working.

23/04/20 20:49:56 (W) gajim.plugin_system        While trying to load clients_icons, exception occurred
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/gajim/plugins/pluginmanager.py", line 666, in scan_dir_for_plugins
    module = __import__(module_name)
  File "/home/crosser/.local/share/gajim/plugins/clients_icons/__init__.py", line 1, in <module>
    from .clients_icons import ClientsIconsPlugin
  File "/home/crosser/.local/share/gajim/plugins/clients_icons/clients_icons.py", line 10, in <module>
    from gajim.common import caps_cache
ImportError: cannot import name 'caps_cache' from 'gajim.common' (/usr/lib/python3/dist-packages/gajim/common/__init__.py)
23/04/20 20:49:56 (W) gajim.plugin_system        Skip Plugin plugin_installer because its already loaded

I looked at the last entries in the logs table in log.db, but nothing caught my eye.

I can send you complete log.db personaly (not as attachment here).

I did some investigation and I am more baffled than I was before. I disable registration of the convertor in order to be able to see data as it was read from the database:

#sqlite.register_converter('disco_info', _convert_disco_info)

and added explicit call to the convertor in the code after SELECT in _load_caps_data() (as well as in _fill_disco_info_cache():

    @timeit
    def _load_caps_data(self):
        '''
        Load caps cache data
        '''
        print("Running load_caps_data")
        rows = self._con.execute(
            'SELECT hash_method, hash, data as "data [disco_info]" '
            'FROM caps_cache')

        for row in rows:
            print(row)
            self._entity_caps_cache[(row.hash_method, row.hash)] = _convert_disco_info(row.data)

So this print(row) prints the same nonsensical junk in the data field:

Running load_caps_data
Row(hash_method='sha-1', hash='AcN1/PEN8nq7AHD+9jpxMV4U6YM=', data=b'\x1f\x8b\x08\x00\xef\xf1L[\x02\xff\x8d\x93\xc1R\xc3 \x10\x86\xf3.=:m\xec\x95\x9b\x07={\xf0\x05\x16\xd8\xa4[\x03\x8b\xb0I\xda\xb7\x97T[3VI.Lv\xbfo\xe0g\x87\x98\x8e\xd0K\x15LU\xbd\x92m\xc9W/\xcfOo\xd5A$\xa8\xba>\x82\xd6\x18w\x1c\xdb:D\x166\xdc\xd5\xfa,\x98$"\xb8T\xd2\x0c\x842?\x80$\x81\xbcW\xc9\xb2\x94\x0co\xc87\xbc\xc2\x12,G"\xadK\xd81\xdb%\xfe\xe0Y\xa89\x17\xb5\xde,\xe0M\x9f0\x96\x1cO\xe6}\x89\xafH\x92\xa8L\xa7\xef\x86:\xac\xa7e+\x11|j\xca\xc1\xa4\xf7\xb8\xc4W\x04;\x1d\xc4u[rWg\x1c\xc7]\xcb\xdcv\xb83\xec\xea\x93\x0ba\xfe\x90\x1cF\xa8\x87\xfd*;aJ\xc4~\x95;\x90E^\xbb\xf1\xc0dp\x92\xbf.\xa4\xe8Cu\x90dV2\xebY5`\xbc\x04\xf9\xee\x9c\x94a\x9f\xa7\x8b\xde`\xd5G\xaf\xa6\xdd\x15\x88\xe4\xbf/k\xeaq\xd6\x1c@ *\x9b\xd7\xbb\xa6C\x81"\xb8N\xff\xc6uNu+\x8e\xe4\xf3\xed\xd4\xfe\xae\x03!$\x15\xf3\x14\n\x08zK\xfc?\xbeL\xf3\x0e_^U\xe0(I\xe5\xf9m{\xfb\xd7\x113)\xc2\xf8[\nY\xfa\xa9\x84\x1c~\x02\xa4a\xeb\xd1\xb5\x04\x00\x00')

but when I query it with sqlite3, it shows reasonable data:

sqlite> select * from caps_cache where hash = 'AcN1/PEN8nq7AHD+9jpxMV4U6YM=';
sha-1|AcN1/PEN8nq7AHD+9jpxMV4U6YM=|<iq xmlns="jabber:client" to="crosser@average.org/pccross" from="tutti@xmpp.ru/1813958839301233987" type="result" id="3247ec99-c863-4018-baf7-a276aa4832cb"><query xmlns="http://jabber.org/protocol/disco#info" node="http://pidgin.im/#AcN1/PEN8nq7AHD+9jpxMV4U6YM="><identity category="client" type="pc" name="Pidgin" /><feature var="jabber:iq:last" /><feature var="jabber:iq:oob" /><feature var="urn:xmpp:time" /><feature var="jabber:iq:version" /><feature var="jabber:x:conference" /><feature var="http://jabber.org/protocol/bytestreams" /><feature var="http://jabber.org/protocol/caps" /><feature var="http://jabber.org/protocol/chatstates" /><feature var="http://jabber.org/protocol/disco#info" /><feature var="http://jabber.org/protocol/disco#items" /><feature var="http://jabber.org/protocol/muc" /><feature var="http://jabber.org/protocol/muc#user" /><feature var="http://jabber.org/protocol/si" /><feature var="http://jabber.org/protocol/si/profile/file-transfer" /><feature var="http://jabber.org/protocol/xhtml-im" /><feature var="urn:xmpp:ping" /><feature var="urn:xmpp:attention:0" /><feature var="urn:xmpp:bob" /><feature var="urn:xmpp:jingle:1" /><feature var="http://www.google.com/xmpp/protocol/session" /><feature var="http://www.google.com/xmpp/protocol/voice/v1" /><feature var="http://www.google.com/xmpp/protocol/video/v1" /><feature var="http://www.google.com/xmpp/protocol/camera/v1" /><feature var="urn:xmpp:jingle:apps:rtp:1" /><feature var="urn:xmpp:jingle:apps:rtp:audio" /><feature var="urn:xmpp:jingle:apps:rtp:video" /><feature var="urn:xmpp:jingle:transports:raw-udp:1" /><feature var="urn:xmpp:jingle:transports:ice-udp:1" /><feature var="urn:xmpp:avatar:metadata" /><feature var="urn:xmpp:avatar:data" /><feature var="urn:xmpp:avatar:metadata+notify" /><feature var="http://jabber.org/protocol/mood" /><feature var="http://jabber.org/protocol/mood+notify" /><feature var="http://jabber.org/protocol/tune" /><feature var="http://jabber.org/protocol/tune+notify" /><feature var="http://jabber.org/protocol/nick" /><feature var="http://jabber.org/protocol/nick+notify" /><feature var="http://jabber.org/protocol/ibb" /></query></iq>|1587669747

Other rows from the cache are read normally.
And if I remove my (rather big) logs.db, the problem disappears.

Looks like a bug in python sqlite bindings? Possibly memory corruption triggered when the amount of data crosses some threshold?

I am on ubuntu focal, sqlite 3.31.1-4, python 3.8.2

what is weird that it disappears when you move your logs.db, cache.db has nothing to do with logs.db

can you show what tables you have in logs.db?

i dont think size has anything to do, what is rather big for you?

can you send me the logs.db to philipp@hoerist.com

then i try to reproduce thanks

what is weird that it disappears when you move your logs.db, cache.db has nothing to do with logs.db

I understand that it is "impossible". It makes me think that the problem might be in sqlite bindings.

I've sent you logs.db (~4Mb)

hi, looking at the logs.db it clear to me why it fails

in the logs.db is a table caps_cache, this table should not be there, the same table is also in cache.db. Both databases are attached to each other at runtime, so sqlite has 2 tables with the same name and chooses to use the one in logs.db, which contains BLOBs in its rows.

So solution is, delete that table from your logs.db, and lets look if this happens again.

Both databases are attached to each other at runtime, so sqlite has 2 tables with the same name and chooses to use the one in logs.db

Wow, I did not even know that it was possible! It also explain the "miracle" that I observed yesterday, when select from caps_cache returned this faulty value even when I saw that the table is empty.

I promise that I did not create the table in log.db!

Sure enough, dropping the table solved the problem. Now I'd need to figure out if it is possible to merge the "new" logs that accumulated in the past few days in the fresh logs.db...

Thanks for you help!

Before closing the ticket, do you think that the code ought to be more resilient to "bad" data? Not good if corrupt data in the database can crash the program...

Now I'd need to figure out if it is possible to merge the "new" logs that accumulated in the past few days in the fresh logs.db...

Naive insert into base.logs (...) select ... from extra.logs; did not work for OMEMO and possibly for other things. Oh well, lost logs for a few days is not such a big deal.

removed needs info label

merging the logs can be tricky, because you would have to make sure there are no duplicates, the order the rows are inserted is also important.

If you value your logs that much, i would not recommend to use nightly.

you can export the logs from the sqlite db with a simple python script and store it in a text file if there is something important in there.

if this happens again with some other user, i would investigate and try to find the problem.

I dont want to distrust my own database and treat it like some external data that i have to guard against.

I don't really know what happend here but lets hope we don't see this again, until then i close

closed

Unfortunately I seem to have had the same issue, see https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=966011, using the stable version 1.2 coming in from debian testing.

Removing caps_cache from logs.db helped also for me. It might be that I have used a nightly version of gajim at some point, probably from debian experimental, because I had other issues with gajim (dark theme-related).

you have to delete the caps_cache table from your logs.db (~/.local/share/gajim)

or you are ok with losing your history that is not stored on the server, and simply delete logs.db

[nightly] Crash on start: app.logger.commit() AttributeError: 'NoneType' object has no attribute 'commit'

Designs

Child items ...

Activity