Loading the plugin crashes client on a regular basis

[AiyionPrime]

Hey there, I think it started a few days back and until then I did not change anything on the clientside.

Bitlbee crashes and reconnects several times an hour, I'm not sure what's triggering it, it is certainly not my user input, as it does so without it as well.

At first I thought it was because my plugin version was oiutdated, so i rebuilt and installed it. Afterwords I hoped, that installing the ubuntu package instead of the make install would resolve it, but it didn't either.

I'm completely clueless for now, if I had to guess, the server was updated, and does no send stuff the plugin cannot handle. Which files or flags are interesting for debugging this further?

[AiyionPrime]

Here's the backtrace:

## BitlBee-LIBPURPLE crashed
## Version: 3.6-1.1ubuntu1
## Configure args: --debug=0 --prefix=/usr --etcdir=/etc/bitlbee --systemdsystemunitdir=/lib/systemd/system --pcdir=/usr/lib/x86_64-linux-gnu/pkgconfig --purple=1
##
## Backtrace:

/usr/sbin/bitlbee(+0x27eef)[0x559a32e48eef]
/usr/sbin/bitlbee(+0x280fa)[0x559a32e490fa]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0)[0x7f8ec0fa83c0]
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0(g_str_hash+0x4)[0x7f8ec1442494]
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0(g_hash_table_lookup+0x2c)[0x7f8ec14415dc]
/usr/lib/purple-2/librocketchat.so(+0xbe30)[0x7f8eb74a3e30]
/usr/lib/purple-2/librocketchat.so(+0xdd0e)[0x7f8eb74a5d0e]
/usr/sbin/bitlbee(+0x29c7c)[0x559a32e4ac7c]
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_context_dispatch+0x14e)[0x7f8ec1453e8e]
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0(+0x52240)[0x7f8ec1454240]
/usr/lib/x86_64-linux-gnu/libglib-2.0.so.0(g_main_loop_run+0x83)[0x7f8ec1454533]
/usr/sbin/bitlbee(main+0x235)[0x559a32e33605]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0x7f8ec0dc80b3]
/usr/sbin/bitlbee(_start+0x2e)[0x559a32e33c1e]

Putting the memory map here seems inappropriate if it's needed say so then i'll put it elsewhere.

[EionRobb]

Hmm... Is it possible to get a debug trace with debug symbols? It's not really clear where the crash is at the moment.

Also, on the bitlbee wiki it talks about how to get a libpurple debug log out of bitlbee by running it with some specific flags. Are you able to get the purple debug log from just before the crash?

[AiyionPrime]

I investigated the Makefile, and couldn't see any stripping parameters, therefore the -g in it should suffice, right? In that case I'll wait for the next crash and report back soon.

I now stopped my bitlbee in forking mode and started it in a screen by hand: BITLBEE_DEBUG=1 bitlbee -Dnv as referenced in https://wiki.bitlbee.org/Debugging

[AiyionPrime]

This does last longer than it did in the last days; if I'm lucky it depends on actions of other users, which could be lacking right now, as it's 04:34 in my timezone. getting back at this tomorrow.

[AiyionPrime]

Well, weekends over, I suppose. I've hit another segfault, this time I've got your debug-output, but as there are other persons names included, I#d like to sent it to you in private. Therefore, you've got mail.

[AiyionPrime]

Due to permission issues, I haven't got a crashlog with symbols, yet I hope to hit another one tomorrow.

[AiyionPrime]

The issue was present with server 3.8.0 and is still in 3.8.1.

[AiyionPrime]

Hmm... Is it possible to get a debug trace with debug symbols? It's not really clear where the crash is at the moment.

Also, on the bitlbee wiki it talks about how to get a libpurple debug log out of bitlbee by running it with some specific flags. Are you able to get the purple debug log from just before the crash?

Huh, sorry. Maybe I did get you wrong. I'd rather not build bitlbee on my server, if it can be helped. Please get back to me, if the output I sent you via mail did not suffice; in which case I'd find time to build bitlbee after submitting my exercises, at the end of the week.

[AiyionPrime]

I can reliably crash the plugin, if I send a message in e.g. the webclient. It crashed, as someone mentioned me, which is what you've got a log for. Happy hunting :/

[EionRobb]

Ok, managed to replicate and traced it back to a data structure change from the server, it used to be

"args": [
            {
                "_id": "NPdxKr69Z4YG8W27Q",
                "rid": "GENERAL",
                "tshow": true,
                "tmid": "6rDhup7BIMSrM22lq",
                "msg": "A very competent installation (i.e.  scalable) of BBB, like Catalyst IT's probably is, would probably perfertly good.  It tears my shorts every time I see gov't sites distributing *any* content in MSFT OOXML fauxpen formats.",
                "ts": {
                    "$date": 1606104963954
                },
                "u": {
                    "_id": "eZqA2i4r76MHt4Y2n",
                    "username": "lightweight",
                    "name": "Dave Lane"
                },
                "_updatedAt": {
                    "$date": 1606104964014
                },
                "mentions": [],
                "channels": []
            },
            {
                "roomParticipant": true,
                "roomType": "c",
                "roomName": "general"
            }
        ]

and now it's

"args": [
            [
                {
                    "_id": "NPdxKr69Z4YG8W27Q",
                    "rid": "GENERAL",
                    "tshow": true,
                    "tmid": "6rDhup7BIMSrM22lq",
                    "msg": "A very competent installation (i.e.  scalable) of BBB, like Catalyst IT's probably is, would probably perfectly good.  It tears my shorts every time I see gov't sites distributing *any* content in MSFT OOXML fauxpen formats.",
                    "ts": {
                        "$date": 1606104963954
                    },
                    "u": {
                        "_id": "eZqA2i4r76MHt4Y2n",
                        "username": "lightweight",
                        "name": "Dave Lane"
                    },
                    "_updatedAt": {
                        "$date": 1606104964014
                    },
                    "mentions": [],
                    "channels": []
                }
            ],
            {
                "roomParticipant": true,
                "roomType": "c",
                "roomName": "general"
            }
        ]

[EionRobb]

Can you give that commit a try?

[AiyionPrime]

Sure. Let me grab a coffee and I'm good to go.

[AiyionPrime]

Your commit does not crash anymore. There seem to be some assertion errors though?

DEBUG rocketchat: got frame data: a["{\"msg\":\"changed\",\"collection\":\"stream-no
tify-user\",\"id\":\"id\",\"fields\":{\"eventName\":\"c5QAp2rWNEyQbZsYR/subscription
s-changed\",\"args\":[\"updated\",{\"_id\":\"4TRpZy9bjWHsDFW7S\",\"open\":true,\"ale
rt\":false,\"unread\":0,\"userMentions\":0,\"groupMentions\":0,\"ts\":{\"$date\":152
2584845012},\"rid\":\"DodqRd9RXgeNBFPxy\",\"name\":\"rocketchat\",\"fname\":null,\"t
\":\"c\",\"u\":{\"_id\":\"c5QAp2rWNEyQbZsYR\",\"username\":\"aiyion\",\"name\":\"AIy
ion\"},\"_updatedAt\":{\"$date\":1606095898398},\"ls\":{\"$date\":1606130706247}}]}}
"]                  
DEBUG rocketchat: got frame data: a["{\"msg\":\"changed\",\"collection\":\"stream-no
tify-user\",\"id\":\"id\",\"fields\":{\"eventName\":\"c5QAp2rWNEyQbZsYR/rooms-change
d\",\"args\":[\"updated\",{\"_id\":\"DodqRd9RXgeNBFPxy\",\"name\":\"rocketchat\",\"t
\":\"c\",\"u\":{\"_id\":\"AuFSZhiWTKBnduXPb\",\"username\":\"sndstrm\"},\"ro\":false
,\"_updatedAt\":{\"$date\":1606130706337},\"lm\":{\"$date\":1606130706280},\"topic\"
:\"Infos und Fragen zum Chat-Tool\",\"lastMessage\":{\"_id\":\"Eois3rRhNbGwovdGn\",\
"rid\":\"DodqRd9RXgeNBFPxy\",\"msg\":\"not this time.\",\"ts\":{\"$date\":1606130706
280},\"u\":{\"_id\":\"c5QAp2rWNEyQbZsYR\",\"username\":\"aiyion\",\"name\":\"Aiyion\
"},\"_updatedAt\":{\"$date\":1606130706331},\"mentions\":[],\"channels\":[]},\"users
Count\":34,\"avatarETag\":\"LZNSvcALzzzTHmgaL\"}]}}"]
DEBUG rocketchat: got frame data: a["{\"msg\":\"changed\",\"collection\":\"stream-no
tify-user\",\"id\":\"id\",\"fields\":{\"eventName\":\"c5QAp2rWNEyQbZsYR/subscription
s-changed\",\"args\":[\"updated\",{\"_id\":\"4TRpZy9bjWHsDFW7S\",\"open\":true,\"ale
rt\":false,\"unread\":0,\"userMentions\":0,\"groupMentions\":0,\"ts\":{\"$date\":152
2584845012},\"rid\":\"DodqRd9RXgeNBFPxy\",\"name\":\"rocketchat\",\"fname\":null,\"t
\":\"c\",\"u\":{\"_id\":\"c5QAp2rWNEyQbZsYR\",\"username\":\"aiyion\",\"name\":\"AIy
ion\"},\"_updatedAt\":{\"$date\":1606130706335},\"ls\":{\"$date\":1606130706335}}]}}
"]                  
DEBUG rocketchat: got frame data: a["{\"msg\":\"changed\",\"collection\":\"stream-ro
om-messages\",\"id\":\"id\",\"fields\":{\"eventName\":\"__my_messages__\",\"args\":[
[{\"_id\":\"Eois3rRhNbGwovdGn\",\"rid\":\"DodqRd9RXgeNBFPxy\",\"msg\":\"not this tim
e.\",\"ts\":{\"$date\":1606130706280},\"u\":{\"_id\":\"c5QAp2rWNEyQbZsYR\",\"usernam
e\":\"aiyion\",\"name\":\"Aiyion\"},\"_updatedAt\":{\"$date\":1606130706331},\"menti
ons\":[],\"channels\":[]}],{\"roomParticipant\":true,\"roomType\":\"c\",\"roomName\":\"rocketchat\"}]}}"]

(process:1167452): Json-CRITICAL **: 12:25:06.532: json_array_get_object_element: assertion 'JSON_NODE_HOLDS_OBJECT (node) || JSON_NODE_HOLDS_NULL (node)' failed

** (process:1167452): CRITICAL **: 12:25:06.533: purple_conv_chat_cb_find: assertion 'chat != NULL' failed

** (process:1167452): CRITICAL **: 12:25:06.533: purple_conv_chat_add_users: assertion 'chat != NULL' failed

** (process:1167452): CRITICAL **: 12:25:06.533: purple_conv_chat_cb_find: assertion 'chat != NULL' failed

** (process:1167452): CRITICAL **: 12:25:06.533: purple_conversation_has_focus: assertion 'conv != NULL' failed

[EionRobb]

(process:1167452): Json-CRITICAL **: 12:25:06.532: json_array_get_object_element: assertion 'JSON_NODE_HOLDS_OBJECT (node) || JSON_NODE_HOLDS_NULL (node)' failed

Ah, so that happens because I'm being a little lazy with the backwards-compat with older Rocket.Chat servers. I'll add in some extra checks to reduce the noise :)

Not sure about the other 4 there.. might be to do with trying to update user lists on a chat/room you don't have open in Pidgin. I'll add some additional checks there too

[EionRobb]

Alright, that commit ^ should silence those warnings :)

Thanks for reporting the bug and confirming the fix :)