#5599 closed defect (fixed)

Ctrl channel does not return any response when malformed command send

Reported by: tomek Owned by: tmark
Priority: medium Milestone: Kea1.4-final
Component: management API Version: git
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: DHCP Feature Depending on Ticket:
Estimated Difficulty: 0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

Kea does not send any response back if the command sent is malformed.
I used the following command:

{
    "command": "reservation-add",
    "arguments": {
        "reservation":
            {
                "subnet-id":1,
                "client-id": "01:0a:0b:0c:0d:0e:0f",
                "ip-address": "192.0.2.205",
    }
}

Note missing closing bracket in reservation scope. Kea should return an error, not close connection silently.

Subtickets

Change History (10)

comment:1 Changed 22 months ago by tomek

  • Milestone changed from Kea-proposed to Kea1.4-final
  • Priority changed from medium to low

As discussed on kea call

comment:2 Changed 21 months ago by tomek

  • Priority changed from low to medium

comment:3 Changed 21 months ago by tmark

  • Owner set to tmark
  • Status changed from new to assigned

comment:4 Changed 21 months ago by tmark

  • Owner changed from tmark to UnAssigned

comment:5 Changed 21 months ago by tmark

  • Owner changed from UnAssigned to tmark

comment:6 Changed 21 months ago by tmark

What I have observed is that using socat to send this text as follows:

cat $1 | sudo socat - UNIX:/tmp/kea-dhcp$2 | python -m json.tool

where $1 is a file containing the text, the server responds as shown below, socat responds immediately with this:

tmark@wild-dog $ ./dofile.sh missing_brace.txt 4
No JSON object could be decoded

and the server logs shows this:

2018-06-04 07:00:42.692 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_OPENED Opened socket 12 for incoming command connection
2018-06-04 07:00:42.693 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_READ Received 229 bytes over command socket 12
2018-06-04 07:00:42.694 INFO  [kea-dhcp4.commands/5455] COMMAND_SOCKET_CLOSED_BY_FOREIGN_HOST Closed command socket 12 by foreign host
2018-06-04 07:00:42.694 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 12 for existing command connection

Socat is closing it's side of connection before the server has timed out waiting for a closing brace. The internal timeout in socat in "batch mode" appears to be extraordinarily short at least for unix sockets and I was unable to alter its behavior with command line flags.

If you run socat interactively and send the same text, the server times and sends back a timed-out error response as one would expect.

tmark@wild-dog $ sudo socat - UNIX:/tmp/kea-dhcp4
{
    "command": "reservation-add",
    "arguments": {
        "reservation":
            {
                "subnet-id":1,
                "client-id": "01:0a:0b:0c:0d:0e:0f",
                "ip-address": "192.0.2.205",
    }
}
{ "result": 1, "text": "Connection over control channel timed out" }

The server logs this:

2018-06-04 07:10:22.798 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_OPENED Opened socket 12 for incoming command connection
2018-06-04 07:10:25.775 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_READ Received 229 bytes over command socket 12
2018-06-04 07:10:33.786 INFO  [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_TIMEOUT Timeout occurred for connection over socket 12
2018-06-04 07:10:33.787 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_CLOSED Closed socket 12 for existing command connection
2018-06-04 07:10:33.787 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_WRITE Sent response of 68 bytes (0 bytes left to send) over command socket -1
2018-06-04 07:10:33.787 ERROR [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_SHUTDOWN_FAIL Encountered error Bad file descriptor while trying to gracefully shutdown socket
2018-06-04 07:10:33.787 DEBUG [kea-dhcp4.commands/5455] COMMAND_SOCKET_CONNECTION_CLOSED Closed socket -1 for existing command connection

Aside from maybe altering the response text to be a little clearer and suggesting users verify their command content in case of problems, there doesn't seem to be much one can really do here.

Last edited 21 months ago by tmark (previous) (diff)

comment:7 Changed 21 months ago by tmark

  • Owner changed from tmark to UnAssigned
  • Status changed from assigned to reviewing

After discussing this in depth with Marcin, we agreed that there really isn't much of anything to fix on the server side. Using a more robust JSON parser would have caught the wrong comma after "ip-address" in this particular case and the user would have gotten an error. However, it would still not avoid the server having to wait for a closing brace. In a case where all received JSON is valid, the server must still wait until it receives an entire command (closing brace) or it times out.

The primary issue encountered here was due to the use of socat in batch mode. I did find a socat option, "ignoreeof", which when ascribed to the client side connection, causes it to wait indefinitely thus allowing the server to timeout and send a timeout response back:

tmark@wild-dog: $ cat missing_brace.txt | sudo socat UNIX:/tmp/kea-dhcp4 -,ignoreeof | python -m json.tool
{
    "result": 1,
    "text": "Connection over control channel timed out, discarded partial command of 229 bytes"
}
tmark@wild-dog: $ 

I updated the user's guide this option. I also modified the control channel logic to include a mention of any discarded data in the timeout response as well as in the log when the client closes the connection.

Ticket is ready for review.

comment:8 Changed 21 months ago by marcin

  • Owner changed from UnAssigned to marcin

comment:9 Changed 21 months ago by marcin

  • Owner changed from marcin to tmark

I reviewed commit e47da044a9ad1dad7e848a7bc05854a0b65f1555. Your changes look good and can be merged. While testing it on macOS, without ignoreeof option I still got the response from the server. So, whether the response is returned or not, is more a matter of an OS. You didn't provide a changelog entry but I am not even sure it is required.

comment:10 Changed 21 months ago by tmark

  • Resolution set to fixed
  • Status changed from reviewing to closed

Changes merged with git# 765bd66b2389bc08c50aaed39390850d33abcf44

I did not add a ChangeLog? entry.

Ticket is complete.

Note: See TracTickets for help on using tickets.