output_mysql generates incorrect SQL queries

[7c]

running inside latest docker on ubuntu20.04 host with docker-cowrie commit e39a583c2451505f5034b3b40d3bfeee7e9adbb1 getting issues at console:

2021-05-22T19:53:12+0000 [-] Timeout reached in CowrieTelnetTransport
2021-05-22T19:53:12+0000 [-] Process ended. Telnet Session disconnected: [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ProcessTerminated'>: A process has ended with a probable error condition: process ended with exit code 1.
    ]
2021-05-22T19:53:12+0000 [twisted.internet.defer#critical] Unhandled error in Deferred:
2021-05-22T19:53:12+0000 [twisted.internet.defer#critical]
    Traceback (most recent call last):
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 517, in errback
        self._startRunCallbacks(fail)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 580, in _startRunCallbacks
        self._runCallbacks()
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 662, in _runCallbacks
        current.result = callback(current.result, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1514, in gotResult
        current_context.run(_inlineCallbacks, r, g, status)
    --- <exception caught here> ---
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1443, in _inlineCallbacks
        result = current_context.run(result.throwExceptionIntoGenerator, g)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 98, in write
        f"SELECT `id`\" \"FROM `sensors`\" \"WHERE `ip` = {self.sensor}"
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 238, in inContext
        result = inContext.theWork()  # type: ignore[attr-defined]
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 255, in <lambda>
        ctx, func, *args, **kw
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 118, in callWithContext
        return self.currentContext().callWithContext(ctx, func, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 83, in callWithContext
        return func(*args, **kw)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 31, in _runInteraction
        return adbapi.ConnectionPool._runInteraction(self, interaction, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 456, in _runInteraction
        compat.reraise(excValue, excTraceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
        return function(*args, **kwargs)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/compat.py", line 403, in reraise
        raise exception.with_traceback(traceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 446, in _runInteraction
        result = interaction(trans, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 459, in _runQuery
        trans.execute(*args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/cursors.py", line 206, in execute
        res = self._query(query)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/cursors.py", line 319, in _query
        db.query(q)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/connections.py", line 259, in query
        _mysql.connection.query(self, query)
    MySQLdb._exceptions.ProgrammingError: (1064, 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near \'" "WHERE `ip` = 246f7ad57fab\' at line 1')

sniffed what was sent to mysql server:

root@mix:/var/log/mysql# ngrep -d ens3 port 3306 |grep -i sensors
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = c10236e10d2c
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = d7f5ebafab52
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = 3ecb3109d841
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = c10236e10d2c
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = 3ecb3109d841
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = 3ecb3109d841
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = 3ecb3109d841
  9....SELECT `id`" "FROM `sensors`" "WHERE `ip` = 3ecb3109d841

there seems to be a formatting issue at first sight.

[7c]

I just realize that this is a cowrie issue at https://github.com/cowrie/cowrie/commit/ec39aad0a01d852f1f74d6e90a99b2405a0738be#r51172072

[micheloosterhof]

Thanks for reporting! Seems like those formatting changes caused some trouble!

[7c]

@micheloosterhof thanks for quick fix, here is new issue you should be aware of:

2021-05-23T14:05:46+0000 [twisted.internet.defer#critical] Unhandled error in Deferred:
2021-05-23T14:05:46+0000 [twisted.internet.defer#critical]
    Traceback (most recent call last):
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 517, in errback
        self._startRunCallbacks(fail)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 580, in _startRunCallbacks
        self._runCallbacks()
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 662, in _runCallbacks
        current.result = callback(current.result, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1514, in gotResult
        current_context.run(_inlineCallbacks, r, g, status)
    --- <exception caught here> ---
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1443, in _inlineCallbacks
        result = current_context.run(result.throwExceptionIntoGenerator, g)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 98, in write
        "SELECT `id`" "FROM `sensors`" f"WHERE `ip` = {self.sensor}"
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 238, in inContext
        result = inContext.theWork()  # type: ignore[attr-defined]
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 255, in <lambda>
        ctx, func, *args, **kw
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 118, in callWithContext
        return self.currentContext().callWithContext(ctx, func, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 83, in callWithContext
        return func(*args, **kw)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 34, in _runInteraction
        raise e
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 31, in _runInteraction
        return adbapi.ConnectionPool._runInteraction(self, interaction, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 456, in _runInteraction
        compat.reraise(excValue, excTraceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
        return function(*args, **kwargs)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/compat.py", line 403, in reraise
        raise exception.with_traceback(traceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 446, in _runInteraction

[micheloosterhof]

This error message is not very helpful. Seems generating the SQL query is failing.

[7c]

would that help?

    2021-05-24T04:08:06+0000 [twisted.internet.defer#critical] Unhandled error in Deferred:
2021-05-24T04:08:06+0000 [twisted.internet.defer#critical]
    Traceback (most recent call last):
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 517, in errback
        self._startRunCallbacks(fail)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 580, in _startRunCallbacks
        self._runCallbacks()
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 662, in _runCallbacks
        current.result = callback(current.result, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1514, in gotResult
        current_context.run(_inlineCallbacks, r, g, status)
    --- <exception caught here> ---
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1443, in _inlineCallbacks
        result = current_context.run(result.throwExceptionIntoGenerator, g)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 98, in write
        "SELECT `id`" "FROM `sensors`" f"WHERE `ip` = {self.sensor}"
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 238, in inContext
        result = inContext.theWork()  # type: ignore[attr-defined]
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 255, in <lambda>
        ctx, func, *args, **kw
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 118, in callWithContext
        return self.currentContext().callWithContext(ctx, func, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 83, in callWithContext
        return func(*args, **kw)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 34, in _runInteraction
        raise e
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 31, in _runInteraction
        return adbapi.ConnectionPool._runInteraction(self, interaction, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 456, in _runInteraction
        compat.reraise(excValue, excTraceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
        return function(*args, **kwargs)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/compat.py", line 403, in reraise
        raise exception.with_traceback(traceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 446, in _runInteraction
        result = interaction(trans, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 459, in _runQuery
        trans.execute(*args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/cursors.py", line 206, in execute
        res = self._query(query)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/cursors.py", line 319, in _query
        db.query(q)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/connections.py", line 259, in query
        _mysql.connection.query(self, query)
    MySQLdb._exceptions.OperationalError: (1054, "Unknown column 'ff406389b682' in 'where clause'")

2021-05-24T04:08:06+0000 [twisted.internet.defer#critical] Unhandled error in Deferred:
2021-05-24T04:08:06+0000 [twisted.internet.defer#critical]
    Traceback (most recent call last):
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 517, in errback
        self._startRunCallbacks(fail)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 580, in _startRunCallbacks
        self._runCallbacks()
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 662, in _runCallbacks
        current.result = callback(current.result, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1514, in gotResult
        current_context.run(_inlineCallbacks, r, g, status)
    --- <exception caught here> ---
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/internet/defer.py", line 1443, in _inlineCallbacks
        result = current_context.run(result.throwExceptionIntoGenerator, g)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/failure.py", line 500, in throwExceptionIntoGenerator
        return g.throw(self.type, self.value, self.tb)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 98, in write
        "SELECT `id`" "FROM `sensors`" f"WHERE `ip` = {self.sensor}"
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 238, in inContext
        result = inContext.theWork()  # type: ignore[attr-defined]
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/threadpool.py", line 255, in <lambda>
        ctx, func, *args, **kw
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 118, in callWithContext
        return self.currentContext().callWithContext(ctx, func, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/context.py", line 83, in callWithContext
        return func(*args, **kw)
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 34, in _runInteraction
        raise e
      File "/cowrie/cowrie-git/src/cowrie/output/mysql.py", line 31, in _runInteraction
        return adbapi.ConnectionPool._runInteraction(self, interaction, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 456, in _runInteraction
        compat.reraise(excValue, excTraceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/deprecate.py", line 298, in deprecatedFunction
        return function(*args, **kwargs)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/python/compat.py", line 403, in reraise
        raise exception.with_traceback(traceback)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 446, in _runInteraction
        result = interaction(trans, *args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/twisted/enterprise/adbapi.py", line 459, in _runQuery
        trans.execute(*args, **kw)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/cursors.py", line 206, in execute
        res = self._query(query)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/cursors.py", line 319, in _query
        db.query(q)
      File "/cowrie/cowrie-env/lib/python3.7/site-packages/MySQLdb/connections.py", line 259, in query
        _mysql.connection.query(self, query)
    MySQLdb._exceptions.OperationalError: (1054, "Unknown column 'ff406389b682' in 'where clause'")

2021-05-24T04:08:06+0000 [cowrie.ssh.userauth.HoneyPotSSHUserAuthServer#debug] b'root' trying auth b'none'

[micheloosterhof]

It's almost like there's some binary data ending up in it.

[7c]

T 172.17.0.2:34694 -> 45.32.165.199:3306 [AP] #13
  3....SELECT `id`FROM `sensors`WHERE `ip` = ff406389b682
#
T 45.32.165.199:3306 -> 172.17.0.2:34694 [AP] #14
  8......#42S22Unknown column 'ff406389b682' in 'where clause'

[micheloosterhof]

I assume your setup was working previously?

[7c]

The commit from 2 weeks ago works, this error is new, i think we need to put " " outer {sensor.self} ?

[7c]

Docker version, no changes

[7c]

[micheloosterhof]

-        if entry["eventid"] == 'cowrie.session.connect':
+        if entry["eventid"] == "cowrie.session.connect":
             r = yield self.db.runQuery(
-                "SELECT `id`"
-                "FROM `sensors`"
-                "WHERE `ip` = %s",
-                (self.sensor,))
+                "SELECT `id`" "FROM `sensors`" f"WHERE `ip` = {self.sensor}"
+            )

This was the change. The unusual double quotes inside the string are because these used to be multiple lines and the black formatter put it all on one line.

[7c]

Yeah i am developer but not a python one... i believe we need to enclosure {self.sensors} within ' .. '

The changes on May 9:

you obviously switches from stringf like to f"" style, the %s was probably " .. " automatically.

[micheloosterhof]

Yes, I get it now. The %s in the old code was actually not a Python string expansion, but it was a MySQL string expansion! https://pynative.com/python-mysql-execute-parameterized-query-using-prepared-statement/

[7c]

next upcoming thing would be the line 105 with insert

[micheloosterhof]

I've been converting old style string formatting in Python to the new f-string format. But this one wasn't an old-style format, it was a special MySQL format string. The conversion is not the same. I'll create a PR.

[7c]

After i have edited

                "SELECT `id`" " FROM `sensors` " f"WHERE `ip` = '{self.sensor}'"
...
                    "INSERT INTO `sensors` (`ip`) " f"VALUES ('{self.sensor}')"

it works, but this might not be the right way to patch. just trying to help you to see next step..

[micheloosterhof]

diff --git a/src/cowrie/output/mysql.py b/src/cowrie/output/mysql.py
index dfabbc2..b16a719 100644
--- a/src/cowrie/output/mysql.py
+++ b/src/cowrie/output/mysql.py
@@ -95,14 +95,14 @@ class Output(cowrie.core.output.Output):
     def write(self, entry):
         if entry["eventid"] == "cowrie.session.connect":
             r = yield self.db.runQuery(
-                "SELECT `id`" "FROM `sensors`" f"WHERE `ip` = {self.sensor}"
+                "SELECT `id` FROM `sensors` WHERE `ip` = %s", (self.sensor,)
             )

             if r:
                 sensorid = r[0][0]
             else:
                 yield self.db.runQuery(
-                    "INSERT INTO `sensors` (`ip`) " f"VALUES ({self.sensor})"
+                    "INSERT INTO `sensors` (`ip`) VALUES (%s)", (self.sensor,)
                 )

                 r = yield self.db.runQuery("SELECT LAST_INSERT_ID()")

I will go back to %s. this is the PR. Could you test?

[micheloosterhof]

https://github.com/cowrie/cowrie/pull/1565

[7c]

seems to work with SELECT

5....INSERT INTO `sensors` (`ip`) VALUES ('ff406389b682')

works, thanks for quick resolution