Telenet server in Twisted gets "Unhandled error in Deferred" errors

I'm trying to make a simple Telnet server that logs the username/password pairs used by the bots out there that try to brute force weak Telnet credentials (Mirai, Gafgyt, etc.). I am trying to use Twisted for this purpose, since it seems to be the state-of-the-art technology for such purposes.

This is what I have made so far:

#!/usr/bin/env python

from twisted.conch.telnet import TelnetTransport, TelnetProtocol, ECHO
from twisted.internet.protocol import ServerFactory
from twisted.application.internet import TCPServer
from twisted.application.service import Application
from twisted.internet import reactor

import logging

class TelnetEcho(TelnetProtocol):

    ip = ''
    user = ''
    state = ''
    line = ''

    def connectionMade(self):
        self.ip = self.transport.getPeer().host
        self.transport.write('Username: ')
        self.transport.will(ECHO)
        self.state = 'User'

    def dataReceived(self, data):
        if self.state != 'Password':
            self.transport.write(data)
        self.line += data
        if data == '\n':
            self.processLine()
            self.line = ''
        return

    def processLine(self):
        if self.state == 'User':
            self.user = self.line.strip()
            self.transport.write('Password: ')
            self.state = 'Password'
        elif self.state == 'Password':
            print 'IP: ' + self.ip + ', user:' + self.user + ', pass:' + self.line.strip()
            logging.info(self.ip + ',' + self.user + ',' + self.line.strip())
            self.transport.write('\r\nIncorrect password or username.\r\n')
            self.transport.write('Username: ')
            self.state = 'User'

def CreateMyFactory():
    factory = ServerFactory()
    factory.protocol = lambda: TelnetTransport(TelnetEcho)
    return factory

if __name__ == "__main__":
    logging.basicConfig(filename='telnet.log', format='%(message)s', level=logging.DEBUG)
    logging.info('Tmestamp,IP,Username,Password')
    for handler in logging.root.handlers[:]:
        logging.root.removeHandler(handler)
    logging.basicConfig(filename='telnet.log', format='%(asctime)s,%(message)s', datefmt='%Y-%m-%d %H:%M:%S', level=logging.DEBUG)
    MyFactory = CreateMyFactory()
    reactor.listenTCP(23, MyFactory)
    reactor.run()

And it works mostly fine - I mean, bots try to log in and it logs the credentials they use - but I keep getting Unhandled error in Deferred errors which leave me completely mystified. I'm not using any deferreds, at least not intentionally. What is causing the errors and how to fix the problem?

Interestingly, the error does not appear if I telnet manually to the server and try to enter a username/password myself; they appear only when the bots are trying to log in. I guess the bots are trying to do something that my server isn't accounting for, but I can't figure out what I am supposed to do.

Edit:

I have changed the above script to use the Twisted logger instead of the Python logger. Now I get some additional information in the log. First, I get the following warning:

2017-09-06 16:17:01+0300 [-] Warning: primary log target selected twice at <c:\python\lib\site-packages\twisted\application\app.py:212> - previously selected at <c:\python\lib\site-packages\twisted\python\log.py:214>.  Remove one of the calls to beginLoggingTo.

I suppose this is some bug in Twisted.

Next, when the "Unhandled error in Deferred" error occurs, I get this i the log:

2017-09-06 16:33:33+0300 [-] Unhandled error in Deferred:
2017-09-06 16:33:33+0300 [-] Unhandled Error
    Traceback (most recent call last):
    Failure: twisted.conch.telnet.OptionRefused: twisted.conch.telnet.OptionRefused:'\x01'

Any ideas how to fix it?

Solution

Here's your use of Deferred:

    self.transport.will(ECHO)

Here are the API docs for will:

def will(option):
    """
    Indicate our willingness to begin performing this option locally.

    Returns a Deferred that fires with True when the peer agrees to allow us
    to begin performing this option, or fails with L{OptionRefused} if the
    peer refuses to allow us to begin performing it.  If the option is
    already enabled locally, the Deferred will fail with L{AlreadyEnabled}.
    If negotiation regarding this option is already in progress, the
    Deferred will fail with L{AlreadyNegotiating}.

    Note: It is currently possible that this Deferred will never fire,
    if the peer never responds, or if the peer believes the option to
    already be enabled.
    """

In your case, the peer is refusing your offer to perform the ECHO function. If you want to suppress the report of this refusal, add an errback to swallow that exception type:

    d = self.transport.will(ECHO)
    d.addErrback(lambda reason: reason.trap(OptionRefused))

Also note that you don't actually have any echo logic in the app so you may want to add that if you're going to offer to do the echo'ing. And you may want to do the will/wont ECHO negotiation around the Password prompt instead of the Username prompt. The point of the will/wont ECHO negotiation is typically to suppress echo of the password.