TheHolyWaffle / TeamSpeak-3-Java-API

A Java wrapper of TeamSpeak's 3 server query API.
MIT License
306 stars 107 forks source link

Asynchronous threads provided by TS3Api class ? #214

Closed Songbird0 closed 5 years ago

Songbird0 commented 7 years ago

Hi !

TL;DR

I'm working on a somewhat stylish TeamSpeak bot and I need to listen onTextMessage events. For my job, no asynchronous tasks are necessary, then I use TS3Api object.

Notice: Despite the substantial source code and logs below, please read carefully. Notice(1): Don't worry about "LE PLUS PRÉCIS" log title. It is french because my OS locales are FR.

Question: For my own, TS3Api should provide synchronous threads only, but it doesn't. Is it a bug or a wanted feature?


I tried this code(I put this code so you can spot the problem via stacktrace):

Don't worry about french comments again, all important informations are english.

public void onTextMessage(TextMessageEvent e) {
    try {
        if (currentInstance.clientWasKicked()) {
            logger.info(String.format("'%1$s' client was kicked from '%2$s' channel.\n" +
                "Thus, this task will be no longer executed.",
                currentClient,
                currentInstance.channelName));
            return;
        } else {
            logger.finer(String.format("client was kicked: %s", currentInstance.clientWasKicked()));
        }
        final TextMessageTargetMode targetMode = e.getTargetMode();
        switch (targetMode) {
            case CLIENT:
                logger.finest("TextMessageTargetMode: CLIENT");
                break;
            case CHANNEL:
                logger.finest("TextMessageTargetMode: CHANNEL");
                break;
            case SERVER:
                logger.finest("TextMessageTargetMode: SERVER");
                break;
        }
        final int invokerId = e.getInvokerId();
        logger.finest(String.format("invokerId: %d", invokerId));
        final int catalogId = CatalogBot.apiInstance.whoAmI().getId();
        logger.finest(String.format("catalogId: %d", catalogId));
        final int currentClientId = CatalogBot.currentClient.getId();
        logger.finest(String.format("currentClientId: %d", currentClientId));
        /* Si le message n'est pas envoyé dans le canal,
         * on stop la méthode, inutile d'aller plus loin.*/
        if (targetMode != TextMessageTargetMode.CHANNEL)
            return;
        /* Si c'est catalog qui parle, inutile d'aller plus loin.
         * Aucun message à traiter.*/
        if (invokerId == catalogId)
            return;
        /* Si quelqu'un d'autre que le client parle dans le canal,
         * on ne retient pas non plus ses messages.
         * Les utilisateurs qui pourraient parler dans ces canaux doivent
         * forcément être des administrateurs, puisque l'accès aux canaux
         * générés est restreint.*/
        if (invokerId != currentClientId)
            return;
        /*Maintenant que nous savons que le message provient bien
        du client se trouvant dans le canal, on peut passer à
        la suite.*/
        // Si la dernière consigne n'a pas encore été donnée:
        if (CatalogBot.currentInstance.step < CatalogBot.currentInstance.botInstructions.length - 1) {
            CatalogBot.currentInstance.computeIdleTime(60 * 3);
        }
        //                                                Ici ^ la task existait mais le client a répondu à temps, donc on
        //                                                annule la task et on en créé une nouvelle pour vérifier qu'il répond
        //                                                à la prochaine consigne.
        final String clientTextMessage = e.getMessage();
        final int stringLength = clientTextMessage.length();
        //                                                Nombre minimum de caractères pour le titre.
        final int titleMinLength = 10;
        //                                                Nombre maximum de caractères pour le titre.
        final int titleMaxLength = 140;
        //                                                Nombre minimum de caractères pour l'explication.
        final int descriptionMinLength = 20;
        //                                                Nombre maximum de caractères pour l'explication.
        final int descriptionMaxLength = 815;
        //                                                Si le catalog vient de demander au client de taper le titre de son
        //                                                ticket et qu'il fait moins de 10 caractères:
        if (CatalogBot.currentInstance.step == 0) {
            if (stringLength < titleMinLength) {
                CatalogBot.apiInstance.sendChannelMessage(
                    String.format("[b][color=red]Vous avez tapé un titre de %1$d caractères. " +
                        "Seulement, votre titre ne doit pas contenir moins de %2$d caractères. " +
                        "Veuillez recommencer svp.[/color][/b]",
                        stringLength,
                        titleMinLength));
                CatalogBot.currentInstance.clientMadeAMistake();
                //                                                    On vérifie que le client n'a pas commis plus de
                //                                                    trois erreurs:
                CatalogBot.currentInstance.useKickHammer("Vous avez commis trop d'erreurs, merci de ne pas spam.");
                return; // on ne souhaite pas que la variable
                // step soit incrémentée alors que le client a fait une erreur,
                // on fait donc un renvoi prématuré ici.
            }
            if (stringLength > titleMaxLength) {
                CatalogBot.apiInstance.sendChannelMessage(
                    String.format("[b][color=red]Vous avez tapé un titre de %1$d caractères. " +
                        "Seulement, votre titre ne doit pas contenir plus de %2$d caractères. " +
                        "Veuillez recommencer svp.[/color][/b]",
                        stringLength,
                        titleMaxLength));
                CatalogBot.currentInstance.clientMadeAMistake();
                //                                                    On vérifie que le client n'a pas commis plus de
                //                                                    trois erreurs:
                CatalogBot.currentInstance.useKickHammer("Vous avez commis trop d'erreurs, merci de ne pas spam.");
                return; // on ne souhaite pas que la variable
                // step soit incrémentée alors que le client a fait une erreur,
                // on fait donc un renvoi prématuré ici.
            }
            //                                                    Si le titre respecte le nombre de caractères minimum, on peut
            //                                                    passer à la suite:
            final ClientInfo clientInfo = CatalogBot.apiInstance.getClientInfo(currentClientId);
            Objects.requireNonNull(clientInfo,
                String.format("Le client (id:%d) n'a pas été trouvé.", currentClientId));
            currentInstance.clientTicket
                .append(currentInstance.stringTemplates[0])
                .append(clientInfo.getNickname())
                .append("\n")
                .append(currentInstance.stringTemplates[1])
                .append(clientTextMessage)
                .append("\n");
        }
        //                                                Si catalog vient de demander au client de taper la description,
        //                                                l'explication de son ticket et qu'elle fait moins de 20 caractères:
        if (currentInstance.step == 1) {
            if (stringLength < descriptionMinLength) {
                CatalogBot.apiInstance.sendChannelMessage(
                    String.format("[b][color=red]Vous avez tapé une description de %1$d caractères. " +
                        "Seulement, votre description ne doit pas contenir moins de %2$d caractères. " +
                        "Veuillez recommencer svp.[/color][/b]",
                        stringLength,
                        descriptionMinLength));
                CatalogBot.currentInstance.clientMadeAMistake();
                //                                                    On vérifie que le client n'a pas commis plus de
                //                                                    trois erreurs:
                CatalogBot.currentInstance.useKickHammer("Vous avez commis trop d'erreurs, merci de ne pas spam.");
                return;
                //                                                    on ne souhaite pas que la variable
                //                                                    step soit incrémentée alors que le client a fait une erreur,
                //                                                    on fait donc un renvoi prématuré ici.
            }
            if (stringLength > descriptionMaxLength) {
                CatalogBot.apiInstance.sendChannelMessage(
                    String.format("[b][color=red]Vous avez tapé une description de %1$d caractères. " +
                        "Seulement, votre description ne doit pas contenir plus de %2$d caractères. " +
                        "Veuillez recommencer svp.[/color][/b]",
                        stringLength,
                        descriptionMaxLength));
                CatalogBot.currentInstance.clientMadeAMistake();
                //                                                    On vérifie que le client n'a pas commis plus de
                //                                                    trois erreurs:
                CatalogBot.currentInstance.useKickHammer("Vous avez commis trop d'erreurs, merci de ne pas spam.");
                return;
            }
            currentInstance.clientTicket
                .append(currentInstance.stringTemplates[2])
                .append(clientTextMessage);
            currentInstance.sendStaffMessage(getList("team_mate").get(), currentInstance.clientTicket.toString());
            currentInstance.deleteChannel();
            CatalogBot.replayCatalog(query);
        }
        CatalogBot.currentInstance.step = CatalogBot.currentInstance.step + 1;
        CatalogBot.currentInstance.sendMessage(currentInstance.step);
    } catch (Exception exception) {
        logger.severe("Query's disconnected.");
        query.exit();
        exception.printStackTrace();
    }
}

I expected to see this happen: All threads are sequentially executed.

Instead, this happened: All onTextMessage() event threads crash because they access to null references. When these threads are executed, the channel in question is already deleted. No additionnal tests are needed.

Meta

Backtrace:

First example, for the Science (!), I tried to spam my bot and look his behavior. ~12 threads were created(i.e. 1 onTextMessage() event, 1 thread/runnable created).

[2017-06-23 18:42:41.272] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:41.384] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:41.521] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:41.581] > whoami
[2017-06-23 18:42:41.581] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:41.581] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:41.689] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:41.761] < [event] notifytextmessage targetmode=2 msg=* invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:41.931] > whoami
[2017-06-23 18:42:41.932] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:41.932] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:41 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:42.282] > whoami
[2017-06-23 18:42:42.282] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:42.282] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:42.601] < [event] notifytextmessage targetmode=2 msg=ff invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:42.632] > whoami
[2017-06-23 18:42:42.632] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:42.633] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:42.704] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:42.832] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1
[2017-06-23 18:42:42.963] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 1

Here, my bot is checking that I made lower than 4 errors:

[2017-06-23 18:42:42.982] > sendtextmessage targetmode=2 target=0 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b]
[2017-06-23 18:42:42.983] < [event] notifytextmessage targetmode=2 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b] invokerid=7 invokername=Catalog invokeruid=serveradmin
[2017-06-23 18:42:42.983] [sendtextmessage] < error id=0 msg=ok
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot clientMadeAMistake
LE PLUS PRÉCIS: 'Songbird' client made 2 errors.
juin 23, 2017 6:42:42 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 7
[2017-06-23 18:42:43.333] > whoami
[2017-06-23 18:42:43.333] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:43.333] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:43 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:43 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:43.683] > whoami
[2017-06-23 18:42:43.683] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:43.684] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:43 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:43 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:44.033] > whoami
[2017-06-23 18:42:44.034] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:44.034] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:44.384] > sendtextmessage targetmode=2 target=0 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b]
[2017-06-23 18:42:44.384] < [event] notifytextmessage targetmode=2 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b] invokerid=7 invokername=Catalog invokeruid=serveradmin
[2017-06-23 18:42:44.384] [sendtextmessage] < error id=0 msg=ok
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 7
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot clientMadeAMistake
LE PLUS PRÉCIS: 'Songbird' client made 3 errors.
[2017-06-23 18:42:44.734] > whoami
[2017-06-23 18:42:44.735] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:44.735] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:45.085] > whoami
[2017-06-23 18:42:45.085] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:45.085] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:45.435] > sendtextmessage targetmode=2 target=0 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b]
[2017-06-23 18:42:45.435] < [event] notifytextmessage targetmode=2 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b] invokerid=7 invokername=Catalog invokeruid=serveradmin
[2017-06-23 18:42:45.436] [sendtextmessage] < error id=0 msg=ok
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot clientMadeAMistake
LE PLUS PRÉCIS: 'Songbird' client made 4 errors.
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'Songbird' made 4 errors.
I'LL USE BAN... KICK HAMMER!
TAKE THIS!
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 7
[2017-06-23 18:42:45.785] > whoami
[2017-06-23 18:42:45.786] [whoami] < virtualserver_status=online virtualserver_id=1 virtualserver_unique_identifier=CEIx0pu\/gYH\/aUcYQSmi+hKczns= virtualserver_port=9987 client_id=7 client_channel_id=96 client_nickname=Catalog client_database_id=1 client_login_name=serveradmin client_unique_identifier=serveradmin client_origin_server_id=0
[2017-06-23 18:42:45.786] [whoami] < error id=0 msg=ok
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: catalogId: 7
juin 23, 2017 6:42:45 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: currentClientId: 1
[2017-06-23 18:42:46.136] > sendtextmessage targetmode=2 target=0 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b]
[2017-06-23 18:42:46.136] < [event] notifytextmessage targetmode=2 msg=[b][color=red]Vous\savez\stapé\sun\stitre\sde\s1\scaractères.\sSeulement,\svotre\stitre\sne\sdoit\spas\scontenir\smoins\sde\s10\scaractères.\sVeuillez\srecommencer\ssvp.[\/color][\/b] invokerid=7 invokername=Catalog invokeruid=serveradmin
[2017-06-23 18:42:46.136] [sendtextmessage] < error id=0 msg=ok
juin 23, 2017 6:42:46 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
PLUS PRÉCIS: client was kicked: false
juin 23, 2017 6:42:46 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: TextMessageTargetMode: CHANNEL
juin 23, 2017 6:42:46 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
LE PLUS PRÉCIS: invokerId: 7
juin 23, 2017 6:42:46 PM fr.privateheberg.catalog.CatalogBot clientMadeAMistake
LE PLUS PRÉCIS: 'Songbird' client made 5 errors.
juin 23, 2017 6:42:46 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'Songbird' made 5 errors.
I'LL USE BAN... KICK HAMMER!
TAKE THIS!

Note these 2(up to 12) logs occurrences "I'LL USE BAN... KICK HAMMER! TAKE THIS!". 'Songbird' cannot be kicked several times, the server connection is throttled.

juin 23, 2017 6:42:50 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: '{client_channel_group_id=5, client_output_muted=0, client_nickname=Songbird, client_is_channel_commander=0, client_platform=Linux, client_type=0, client_unique_identifier=2WUaxqgJK8I40VKsVZotyJYAdKo=, client_database_id=2, client_output_hardware=1, client_version=3.0.19.4 [Build: 1468491418], client_icon_id=0, client_is_talker=0, client_created=1494350960, client_idle_time=353, clid=1, client_talk_power=75, client_flag_talking=0, connection_client_ip=92.155.129.179, client_input_muted=0, client_is_recording=0, client_is_priority_speaker=0, client_lastconnected=1498245172, client_channel_group_inherited_channel_id=5, client_input_hardware=0, client_country=FR, client_away_message=, client_servergroups=2,6, cid=5, client_away=0}' client was kicked from 'Aide #786714548' channel.
Thus, this task will be no longer executed.
[2017-06-23 18:42:50.834] [SEVERE] Command quit was not answered in time.
java.lang.NullPointerException
        at fr.privateheberg.catalog.CatalogBot$CatalogTextEvent.onTextMessage(CatalogBot.java:1605)
        at com.github.theholywaffle.teamspeak3.api.event.TextMessageEvent.fire(TextMessageEvent.java:55)
        at com.github.theholywaffle.teamspeak3.EventManager.fireEvent(EventManager.java:55)
        at com.github.theholywaffle.teamspeak3.SocketReader$1.run(SocketReader.java:99)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
        at fr.privateheberg.catalog.CatalogBot$CatalogTextEvent.onTextMessage(CatalogBot.java:1605)
        at com.github.theholywaffle.teamspeak3.api.event.TextMessageEvent.fire(TextMessageEvent.java:55)
        at com.github.theholywaffle.teamspeak3.EventManager.fireEvent(EventManager.java:55)
        at com.github.theholywaffle.teamspeak3.SocketReader$1.run(SocketReader.java:99)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
java.lang.NullPointerException
        at fr.privateheberg.catalog.CatalogBot$CatalogTextEvent.onTextMessage(CatalogBot.java:1605)
        at com.github.theholywaffle.teamspeak3.api.event.TextMessageEvent.fire(TextMessageEvent.java:55)
        at com.github.theholywaffle.teamspeak3.EventManager.fireEvent(EventManager.java:55)
        at com.github.theholywaffle.teamspeak3.SocketReader$1.run(SocketReader.java:99)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
juin 23, 2017 6:42:51 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'clientWasKicked' was bound to 'true'.
juin 23, 2017 6:42:51 PM fr.privateheberg.catalog.CatalogBot$IdlersKicker run
LE PLUS PRÉCIS: 'Songbird' idle time: 5 seconds.
juin 23, 2017 6:42:51 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'clientWasKicked' was bound to 'true'.
juin 23, 2017 6:42:51 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:51 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'clientWasKicked' was bound to 'true'.
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
java.lang.NullPointerException
        at fr.privateheberg.catalog.CatalogBot$CatalogTextEvent.onTextMessage(CatalogBot.java:1605)
        at com.github.theholywaffle.teamspeak3.api.event.TextMessageEvent.fire(TextMessageEvent.java:55)
        at com.github.theholywaffle.teamspeak3.EventManager.fireEvent(EventManager.java:55)
        at com.github.theholywaffle.teamspeak3.SocketReader$1.run(SocketReader.java:99)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot$IdlersKicker run
LE PLUS PRÉCIS: 'Songbird' idle time: 6 seconds.
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:52 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'clientWasKicked' was bound to 'true'.
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'clientWasKicked' was bound to 'true'.
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
GRAVE: Query's disconnected.
java.lang.NullPointerException
        at fr.privateheberg.catalog.CatalogBot$CatalogTextEvent.onTextMessage(CatalogBot.java:1605)
        at com.github.theholywaffle.teamspeak3.api.event.TextMessageEvent.fire(TextMessageEvent.java:55)
        at com.github.theholywaffle.teamspeak3.EventManager.fireEvent(EventManager.java:55)
        at com.github.theholywaffle.teamspeak3.SocketReader$1.run(SocketReader.java:99)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot$IdlersKicker run
LE PLUS PRÉCIS: 'Songbird' idle time: 7 seconds.
juin 23, 2017 6:42:53 PM fr.privateheberg.catalog.CatalogBot useKickHammer
LE PLUS PRÉCIS: 'clientWasKicked' was bound to 'true'.
java.lang.NullPointerException
        at fr.privateheberg.catalog.CatalogBot$CatalogTextEvent.onTextMessage(CatalogBot.java:1605)
        at com.github.theholywaffle.teamspeak3.api.event.TextMessageEvent.fire(TextMessageEvent.java:55)
        at com.github.theholywaffle.teamspeak3.EventManager.fireEvent(EventManager.java:55)
        at com.github.theholywaffle.teamspeak3.SocketReader$1.run(SocketReader.java:99)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

Solution

I tried to fix this problem myself by adding a synchronized mutex on onTextMessage method signature, and it works!

However, like expected, my logs report a 'null' reference:

Spam:

[2017-06-23 20:41:36.201] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:36.321] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:36.449] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:36.586] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:36.835] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
juin 23, 2017 8:41:36 PM fr.privateheberg.catalog.CatalogBot$IdlersKicker run
LE PLUS PRÉCIS: 'Songbird' idle time: 3 seconds.
[2017-06-23 20:41:36.938] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:37.184] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:37.320] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:37.433] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=
[2017-06-23 20:41:37.584] < [event] notifytextmessage targetmode=2 msg=f invokerid=1 invokername=Songbird invokeruid=2WUaxqgJK8I40VKsVZotyJYAdKo=

Response:

juin 23, 2017 8:41:43 PM fr.privateheberg.catalog.CatalogBot deleteChannel
LE PLUS PRÉCIS: Catalog listeners unregistered.
[2017-06-23 20:41:43.976] > channeldelete cid=98 force=1
[2017-06-23 20:41:43.978] [channeldelete] < error id=0 msg=ok
juin 23, 2017 8:41:43 PM fr.privateheberg.catalog.CatalogBot deleteChannel
LE PLUS PRÉCIS: 'Aide #589402250' channel deleted.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot deleteChannel
LE PLUS PRÉCIS: current task canceled !
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.
juin 23, 2017 8:41:44 PM fr.privateheberg.catalog.CatalogBot$CatalogTextEvent onTextMessage
INFOS: 'null' client was kicked from 'Aide #589402250' channel.
Thus, this task will be no longer executed.

All threads are terminated properly and there is no NPE, yay! :D

Kakifrucht commented 7 years ago

Funny you should mention it now, afaik @rogermb talked about this a couple of days ago on Gitter and I'm pretty sure he fixed it (Didn't commit it just yet), if I understood your problem correctly.

Songbird0 commented 7 years ago

Hey you! :)

Thanks for the mention.

if I understood your problem correctly.

It's simple, supposing that 3 threads are created to listen onTextMessage() event.

Implementation:

@Override
public void onTextMessage(TextMessageEvent e){
    apiInstance.whoAmI().getId(); // will get an error
}
  1. First thread will perform whoAmI().getId() call chain without any problem;
  2. Channel deletion;
  3. Second thread will get a NPE;
  4. Third thread will get a NPE too.

You understood this thing, initially ? :)

rogermb commented 7 years ago

Hi again!

We actually recently had a discussion on thread safety and ordering guarantees in event listeners, as @Kakifrucht mentioned. Sorry I couldn't respond to you faster, but I wanted to take my time on this. (And I also needed sleep and had some real-life obligations 😛)

Current situation

Currently, there are no thread safety or ordering guarantees in event listeners. This has been the case in this project since the very first commit.

If your event listener isn't a pure function (no side effects), then your event listener code needs to be not just sequentially, but also concurrently correct. That means that you'll need to synchronize your field accesses, make sure there are no race conditions, somehow prevent reorderings (that one's tough), etc.

This is why your code doesn't work properly. The event listener is simply running multiple times at once (for different events).

Future

In the upcoming release of version 1.1, this behavior will change.

There will still not be "a single thread" for all event listeners, as this could negatively affect the performance too much. For example, that would make it possible for one event listener to block all other event listeners from running.

Instead, there will be a strict ordering of events per event listener. That means each event listener you register will only ever be executing one onXYZ method at a time. Furthermore, it will no longer be possible for events to get reordered.

This effectively gives you a guarantee that you can access all fields and all parts of memory that are not shared outside the event listener without requiring synchronization.

I guess this also emphasizes decoupling different event listeners and splitting them up into different classes. That way, those event listeners that don't affect each other could run at the same time, when they couldn't if they were implemented in the same class.


Apart from all that, you're also running into command timeout problems. If you're filling the command queue faster than what the socket / flood rate settings can handle, some commands will eventually time out. In the current version, all synchronous commands have a built-in "countdown timer". If it reaches 0, the command is kicked from the queue and null is returned. This, too, will change in the next release.

Kakifrucht commented 7 years ago

Thanks, I recompiled to test your changes, looks good out of the box.

Songbird0 commented 7 years ago

Hi,

Sorry I couldn't respond to you faster, but I wanted to take my time on this. (And I also needed sleep and had some real-life obligations :stuck_out_tongue:)

No problem!

If your event listener isn't a pure function (no side effects), then your event listener code needs to be not just sequentially, but also concurrently correct. That means that you'll need to synchronize your field accesses, make sure there are no race conditions, somehow prevent reorderings (that one's tough), etc.

All right. I'll do my best to synchronize properly my resources. By the way, (if the logs are removed) my "solution" sounds be correct.

Thanks all!

Regards.

rogermb commented 5 years ago

Completely forgot about this issue. The threading guarantees mentioned in my last comment were added in v1.1.0, which was released almost half a year ago 😄. Closed