>18 lines sent by TLSSupport.message getting lost

[drlight-code]

Hi, I am running pydle master on our fileserver, which also hosts our IRC server, in order to send status information about raid health/usage etc. into our private discussion channel.

Messages are being lost, if I send more than 18 lines from a single on_message handler. It seems to me that there is some internal buffer or queue overflowing. I tried throttling send rate in my own code, but the messages will only appear if my code finished the on_message handler so that's not helping. Also I'm pretty sure it's not sending rate related, our server is not configured in any way regarding that, and I wrote irssi scripts the other day which quickly generate screens full of text, and that is displayed just fine. I also tried setting self.connection.throttle = True which did not change anything.

I started tracking this down in the pydle code and for now stopped at the point where the asynchronous processing in tornado.ioloop begins. I suspect that either

• I am using message wrong / at the wrong place, meaning inside the on_message handler (most likely)
• There is some internal send queue size limitation
• When pulling messages from the queue there are threading issues / race conditions of some sort

Thanks in advance

[shizmob]

Hi! Thanks for reporting this, I'm going to take a look at it.

By eighteen lines, do you mean eighteen separate invocations of Client.message(), or a message contain eighteen newline (\n) characters? The latter will pose problems. The former should be supported, so that would be a bug if it's not working.

Is there any pattern to the lost messages? For instance, are only the first few or last few messages lost, or are random messages in the queue lost?

As a sidenote, Client.connection.throttle is automatically set to True by pydle when the IRC registration (connection set-up) is finished, so setting it yourself is not needed.

[drlight-code]

I was sending most of them as single lines, but one block of 4 lines as a single message. Changed this to only sending single lines at a time now. Looking at the implementation of message in rfc1459/client.py it seems that the splitting into lines is already performed internally, however:

        for line in message.replace('\r', '').split('\n'):
            for chunk in chunkify(line, chunklen):
                self.rawmsg('PRIVMSG', target, chunk)

Here's my relevant code:

    def printRaidInfo(self):
        self.message("Reporting RAID status: files.saunaklub.net")
        self.message(" ")

        self.commandToChannel("sudo mdadm --detail /dev/md0 | sed -n '13,+5p; 25,+4p'")

        message = ""
        for letter in ['b', 'c', 'd', 'e']:
            message += '/dev/sd' + letter + ': '
            message += self.commandToString('sudo smartctl -H /dev/sd' + letter +
                                            ' | grep "self-assessment test"')
        self.message(message)

    def commandToString(self, command):
        process = subprocess.Popen(['bash', '-c', command],
                                   stdin=subprocess.PIPE,
                                   stdout=subprocess.PIPE)

        out, _ = process.communicate()
        return out.decode('utf-8')

    def commandToChannel(self, command):
        process = subprocess.Popen(['bash', '-c', command],
                                   stdin=subprocess.PIPE,
                                   stdout=subprocess.PIPE)

        out, _ = process.communicate()
        out = out.decode('utf-8').replace('\r', '')

        self.message(out)

    def message(self, message):
        for line in message.split('\n'):
            if(line == ''):
                line = ' '
            print("sending message: " + line)
            super().message(channel, line)

I do the splitting myself still since I don't want empty lines to be swallowed, replacing them by a single space. This gives me the following output on the terminal:

sending message: Reporting RAID status: files.saunaklub.net
sending message:  
sending message:           State : clean 
sending message:  Active Devices : 4
sending message: Working Devices : 4
sending message:  Failed Devices : 0
sending message:   Spare Devices : 0
sending message:  
sending message:     Number   Major   Minor   RaidDevice State
sending message:        0       8       65        0      active sync   /dev/sde1
sending message:        1       8       33        1      active sync   /dev/sdc1
sending message:        2       8       17        2      active sync   /dev/sdb1
sending message:        3       8       49        3      active sync   /dev/sdd1
sending message:  
sending message: /dev/sdb: SMART overall-health self-assessment test result: PASSED
sending message: /dev/sdc: SMART overall-health self-assessment test result: PASSED
sending message: /dev/sdd: SMART overall-health self-assessment test result: PASSED
sending message: /dev/sde: SMART overall-health self-assessment test result: PASSED

However in the channel, all I see is:

13:17 < saunaboy> Reporting RAID status: files.saunaklub.net
13:17 < saunaboy>  
13:17 < saunaboy>           State : clean 
13:17 < saunaboy>  Active Devices : 4
13:17 < saunaboy> Working Devices : 4
13:17 < saunaboy>  Failed Devices : 0
13:17 < saunaboy>   Spare Devices : 0
13:17 < saunaboy>  
13:17 < saunaboy>     Number   Major   Minor   RaidDevice State
13:17 < saunaboy>        0       8       65        0      active sync   /dev/sde1
13:17 < saunaboy>        1       8       33        1      active sync   /dev/sdc1
13:17 < saunaboy>        2       8       17        2      active sync   /dev/sdb1
13:17 < saunaboy>        3       8       49        3      active sync   /dev/sdd1
13:17 < saunaboy>  
13:17 < saunaboy> /dev/sdb: SMART overall-health self-assessment test result: PASSED
13:17 < saunaboy> /dev/sdc: SMART overall-health self-assessment test result: PASSED

It does not count up to 18 because I send two lines (separately) as a preamble before that, but that should not be relevant.

[shizmob]

After some live debugging with @flv0 on IRC, the issue was determined to be a combination of pydle's throttle model and Charybdis' dropping of messages it presumes to be part of a flood.

I've opened #28 to discuss a better implementation of pydle's flood model.