Error logging found in stream to client (security issue)

[edwin-oetelaar]

I have found that a badly behaving client (mqtt spy running out of memory)
can make mosquito version 1.4.14 close socket(0) somehow.
(running linux)

This means that a newly connection client gets socket with number 0 or 1 and so also gets stdout/stderr intermixed with the normal protocol.

This looks like : (wireshark grap)

.p...#..'...#.......6...;......e....sO?z........................V
...Kyd..x....8S......(l...p....."@<....w..Z......e...o.....M.7...'._..g..........................1512729645: Socket error on client , disconnecting.
1512729645: New connection from 172.17.0.1 on port 1883.
1512729645: Client bd-00:1c:c0:b1:de:50 disconnected.
1512729645: New client connected from 172.17.0.1 as bd-00:1c:c0:b1:de:50 (c0, k10, u'bierserver').
1512729793: Socket error on client oetelaar_mqttspy123, disconnecting.
1512729793: New connection from 172.17.0.1 on port 1883.
1512729793: New client connected from 172.17.0.1 as oetelaar_mqttspy123 (c1, k60).
1512729804: Client bd-00:1c:c0:b1:de:50 has exceeded timeout, disconnecting.

This prevents the client from connecting, but it is a symptom of something far more serious.
I will investigate, but maybe some else can look into it too.
Best regards,
Edwin van den Oetelaar

Update : after looking more in detail, it looks like close(1) is performed, stderr ends up in stream
Update2 : I am not sure if fd=0 or fd=1 or something else is writing to the socket.
It might also be that the log-file is closed (from out of disk space) and the logger writes into the known fd, which is now re-used as a new socket-fd, which causes the logging to end up in the socket-stream.
I have come to this conclusion because the redirected stdout contains full logging, including the data that was found in the stream.
Update3: I can not trigger the problem, however I have seen it in the wild at least 4 times, I will investigate more
Update4: I have compiled 1.4.14 on linux ubuntu 14.04 and tested and can not trigger the problem, the setup with the problem is a docker image https://hub.docker.com/r/toke/mosquitto/

Update 5: 25/12/2017 It happened again (wireshark dump)

data from client

00000000  10 1f 00 04 4d 51 54 54  04 02 00 3c 00 13 6f 65 ....MQTT ...<..oe
00000010  74 65 6c 61 61 72 5f 6d  71 74 74 73 70 79 31 32 telaar_m qttspy12
00000020  33                                               3

reply from mqtt server

00000000  31 35 31 34 31 39 37 36  37 37 3a 20 4e 65 77 20 15141976 77: New 
00000010  63 6f 6e 6e 65 63 74 69  6f 6e 20 66 72 6f 6d 20 connecti on from 
00000020  31 37 32 2e 31 37 2e 30  2e 31 20 6f 6e 20 70 6f 172.17.0 .1 on po
00000030  72 74 20 31 38 38 33 2e  0a                      rt 1883. .

then a retry, see protocol version changed:

00000000  10 21 00 06 4d 51 49 73  64 70 03 02 00 3c 00 13 .!..MQIs dp...<..
00000010  6f 65 74 65 6c 61 61 72  5f 6d 71 74 74 73 70 79 oetelaar _mqttspy
00000020  31 32 33                                         123

    00000000  31 35 31 34 31 39 37 36  37 37 3a 20 4e 65 77 20 15141976 77: New 
    00000010  63 6f 6e 6e 65 63 74 69  6f 6e 20 66 72 6f 6d 20 connecti on from 
    00000020  31 37 32 2e 31 37 2e 30  2e 31 20 6f 6e 20 70 6f 172.17.0 .1 on po
    00000030  72 74 20 31 38 38 33 2e  0a                      rt 1883. .

This one is even more interesting, the connection happens syn/ack but the server does not wait.. it just dumps data to the client before client can send anything, it then handles some of the protocol but dumps the info in the stream again.

    00000000  31 35 31 34 31 39 37 36  38 32 3a 20 4e 65 77 20 15141976 82: New 
    00000010  63 6f 6e 6e 65 63 74 69  6f 6e 20 66 72 6f 6d 20 connecti on from 
    00000020  31 37 32 2e 31 37 2e 30  2e 31 20 6f 6e 20 70 6f 172.17.0 .1 on po
    00000030  72 74 20 31 38 38 33 2e  0a                      rt 1883. .

00000000  10 1f 00 04 4d 51 54 54  04 02 00 3c 00 13 6f 65 ....MQTT ...<..oe
00000010  74 65 6c 61 61 72 5f 6d  71 74 74 73 70 79 31 32 telaar_m qttspy12
00000020  33                                               3

    00000039  31 35 31 34 31 39 37 36  38 32 3a 20 4e 65 77 20 15141976 82: New 
    00000049  63 6c 69 65 6e 74 20 63  6f 6e 6e 65 63 74 65 64 client c onnected
    00000059  20 66 72 6f 6d 20 31 37  32 2e 31 37 2e 30 2e 31  from 17 2.17.0.1
    00000069  20 61 73 20 6f 65 74 65  6c 61 61 72 5f 6d 71 74  as oete laar_mqt
    00000079  74 73 70 79 31 32 33 20  28 63 31 2c 20 6b 36 30 tspy123  (c1, k60
    00000089  29 2e 0a                                         )..

This continues a while

00000000  10 21 00 06 4d 51 49 73  64 70 03 02 00 3c 00 13 .!..MQIs dp...<..
00000010  6f 65 74 65 6c 61 61 72  5f 6d 71 74 74 73 70 79 oetelaar _mqttspy
00000020  31 32 33                                         123

    00000000  31 35 31 34 31 39 37 36  38 32 3a 20 4e 65 77 20 15141976 82: New 
    00000010  63 6f 6e 6e 65 63 74 69  6f 6e 20 66 72 6f 6d 20 connecti on from 
    00000020  31 37 32 2e 31 37 2e 30  2e 31 20 6f 6e 20 70 6f 172.17.0 .1 on po
    00000030  72 74 20 31 38 38 33 2e  0a                      rt 1883. .

and then after about 15 failed connects it works

00000000  10 21 00 06 4d 51 49 73  64 70 03 02 00 3c 00 13 .!..MQIs dp...<..
00000010  6f 65 74 65 6c 61 61 72  5f 6d 71 74 74 73 70 79 oetelaar _mqttspy
00000020  31 32 33                                         123
    00000000  20 02 00 00                                       ...
00000023  82 09 00 01 00 04 74 65  73 74 00                ......te st.
    00000004  90 03 00 01 00                                   .....
0000002E  82 0b 00 02 00 06 74 65  73 74 2f 2b 00          ......te st/+.
    00000009  90 03 00 02 00                                   .....
0000003B  82 0d 00 03 00 08 74 65  73 74 2f 2b 2f 2b 02    ......te st/+/+.
    0000000E  90 03 00 03 02                                   .....
    00000013  31 3a 00 20 74 65 73 74  2f 62 74 2d 62 38 3a 32 1:. test /bt-b8:2
    00000023  37 3a 65 62 3a 38 63 3a  38 30 3a 65 33 2f 73 74 7:eb:8c: 80:e3/st
    00000033  61 74 75 73 63 6f 6e 6e  65 63 74 65 64 3a 31 39 atusconn ected:19
    00000043  32 2e 31 36 38 2e 31 2e  31 37 33 0a 31 3a 00 20 2.168.1. 173.1:. 
    00000053  74 65 73 74 2f 62 74 2d  62 38 3a 32 37 3a 65 62 test/bt- b8:27:eb
    00000063  3a 33 31 3a 61 33 3a 37  38 2f 73 74 61 74 75 73 :31:a3:7 8/status
    00000073  63 6f 6e 6e 65 63 74 65  64 3a 31 39 32 2e 31 36 connecte d:192.16
    00000083  38 2e 38 2e 31 34 38 0a  33 30 00 20 74 65 73 74 8.8.148. 30. test
    00000093  2f 62 74 2d 62 38 3a 32  37 3a 65 62 3a 61 39 3a /bt-b8:2 7:eb:a9:
    000000A3  36 37 3a 63 31 2f 73 74  61 74 75 73 00 01 64 69 67:c1/st atus..di
    000000B3  73 63 6f 6e 6e 65 63 74  65 64 31 39 00 20 74 65 sconnect ed19. te
    000000C3  73 74 2f 62 74 2d 62 38  3a 32 37 3a 65 62 3a 33 st/bt-b8 :27:eb:3
    000000D3  38 3a 66 31 3a 30 61 2f  73 74 61 74 75 73 63 6f 8:f1:0a/ statusco
    000000E3  6e 6e 65 63 74 65 64 3a  31 39 32 2e 31 36 38 2e nnected: 192.168.
    000000F3  31 2e 32 37 0a 33 30 00  20 74 65 73 74 2f 62 74 1.27.30.  test/bt
    00000103  2d 62 38 3a 32 37 3a 65  62 3a 32 32 3a 34 61 3a -b8:27:e b:22:4a:
    00000113  36 35 2f 73 74 61 74 75  73 00 02 64 69 73 63 6f 65/statu s..disco
    00000123  6e 6e 65 63 74 65 64 33  30 00 20 74 65 73 74 2f nnected3 0. test/
    00000133  62 74 2d 62 38 3a 32 37  3a 65 62 3a 34 35 3a 33 bt-b8:27 :eb:45:3
    00000143  35 3a 35 62 2f 73 74 61  74 75 73 00 03 64 69 73 5:5b/sta tus..dis
    00000153  63 6f 6e 6e 65 63 74 65  64 33 30 00 20 74 65 73 connecte d30. tes
    00000163  74 2f 62 74 2d 62 38 3a  32 37 3a 65 62 3a 31 66 t/bt-b8: 27:eb:1f
    00000173  3a 65 35 3a 63 38 2f 73  74 61 74 75 73 00 04 64 :e5:c8/s tatus..d
    00000183  69 73 63 6f 6e 6e 65 63  74 65 64 33 30 00 20 74 isconnec ted30. t
    00000193  65 73 74 2f 62 74 2d 62  38 3a 32 37 3a 65 62 3a est/bt-b 8:27:eb:
    000001A3  65 37 3a 63 39 3a 34 35  2f 73 74 61 74 75 73 00 e7:c9:45 /status.
    000001B3  05 64 69 73 63 6f 6e 6e  65 63 74 65 64 33 30 00 .disconn ected30.
    000001C3  20 74 65 73 74 2f 62 74  2d 62 38 3a 32 37 3a 65  test/bt -b8:27:e
    000001D3  62 3a 35 31 3a 61 65 3a  35 35 2f 73 74 61 74 75 b:51:ae: 55/statu
    000001E3  73 00 06 64 69 73 63 6f  6e 6e 65 63 74 65 64 33 s..disco nnected3
    000001F3  30 00 20 74 65 73 74 2f  62 74 2d 62 38 3a 32 37 0. test/ bt-b8:27
    00000203  3a 65 62 3a 38 35 3a 37  61 3a 62 36 2f 73 74 61 :eb:85:7 a:b6/sta
    00000213  74 75 73 00 07 64 69 73  63 6f 6e 6e 65 63 74 65 tus..dis connecte
    00000223  64 31 3a 00 20 74 65 73  74 2f 62 74 2d 62 38 3a d1:. tes t/bt-b8:
    00000233  32 37 3a 65 62 3a 64 30  3a 34 61 3a 30 36 2f 73 27:eb:d0 :4a:06/s
    00000243  74 61 74 75 73 63 6f 6e  6e 65 63 74 65 64 3a 31 tatuscon nected:1
    00000253  39 32 2e 31 36 38 2e 38  2e 31 33 30 0a 33 30 00 92.168.8 .130.30.
    00000263  20 74 65 73 74 2f 62 74  2d 62 38 3a 32 37 3a 65  test/bt -b8:27:e
    00000273  62 3a 38 35 3a 39 63 3a  62 39 2f 73 74 61 74 75 b:85:9c: b9/statu
    00000283  73 00 08 64 69 73 63 6f  6e 6e 65 63 74 65 64 33 s..disco nnected3
    00000293  30 00 20 74 65 73 74 2f  62 74 2d 62 38 3a 32 37 0. test/ bt-b8:27
    000002A3  3a 65 62 3a 66 62 3a 32  61 3a 32 64 2f 73 74 61 :eb:fb:2 a:2d/sta
    000002B3  74 75 73 00 09 64 69 73  63 6f 6e 6e 65 63 74 65 tus..dis connecte
    000002C3  64 33 30 00 20 74 65 73  74 2f 62 74 2d 62 38 3a d30. tes t/bt-b8:
    000002D3  32 37 3a 65 62 3a 63 33  3a 61 37 3a 65 34 2f 73 27:eb:c3 :a7:e4/s
    000002E3  74 61 74 75 73 00 0a 64  69 73 63 6f 6e 6e 65 63 tatus..d isconnec
    000002F3  74 65 64 35 2d 00 20 74  65 73 74 2f 6e 72 2d 30 ted5-. t est/nr-0
    00000303  30 3a 30 30 3a 30 30 3a  30 30 3a 30 30 3a 30 30 0:00:00: 00:00:00
    00000313  2f 73 74 61 74 75 73 00  0b 63 6f 6e 6e 65 63 74 /status. .connect
    00000323  65 64 33 3a 00 20 74 65  73 74 2f 62 74 2d 62 38 ed3:. te st/bt-b8
    00000333  3a 32 37 3a 65 62 3a 61  61 3a 30 32 3a 30 33 2f :27:eb:a a:02:03/
    00000343  73 74 61 74 75 73 00 0c  63 6f 6e 6e 65 63 74 65 status.. connecte
    00000353  64 3a 31 39 32 2e 31 36  38 2e 31 2e 37 0a 31 39 d:192.16 8.1.7.19
    00000363  00 20 74 65 73 74 2f 62  64 2d 30 30 3a 31 63 3a . test/b d-00:1c:
    00000373  63 30 3a 62 31 3a 64 65  3a 35 30 2f 73 74 61 74 c0:b1:de :50/stat
    00000383  75 73 63 6f 6e 6e 65 63  74 65 64 3a 31 39 32 2e usconnec ted:192.
    00000393  31 36 38 2e 31 2e 31 30  31 33 30 00 20 74 65 73 168.1.10 130. tes
    000003A3  74 2f 62 73 2d 30 30 3a  31 63 3a 63 30 3a 62 31 t/bs-00: 1c:c0:b1
    000003B3  3a 64 65 3a 35 30 2f 73  74 61 74 75 73 00 0d 64 :de:50/s tatus..d
    000003C3  69 73 63 6f 6e 6e 65 63  74 65 64 31 3b 00 20 74 isconnec ted1;. t
    000003D3  65 73 74 2f 62 74 2d 62  38 3a 32 37 3a 65 62 3a est/bt-b 8:27:eb:
    000003E3  37 35 3a 62 35 3a 66 38  2f 73 74 61 74 75 73 63 75:b5:f8 /statusc
    000003F3  6f 6e 6e 65 63 74 65 64  3a 31 39 32 2e 31 36 38 onnected :192.168
    00000403  2e 31 2e 36 33 3a 4f 6b  31 3c 00 20 74 65 73 74 .1.63:Ok 1<. test
    00000413  2f 62 74 2d 62 38 3a 32  37 3a 65 62 3a 61 35 3a /bt-b8:2 7:eb:a5:
    00000423  33 36 3a 32 39 2f 73 74  61 74 75 73 63 6f 6e 6e 36:29/st atusconn
    00000433  65 63 74 65 64 3a 31 39  32 2e 31 36 38 2e 31 2e ected:19 2.168.1.
    00000443  31 36 32 3a 4f 6b 31 3b  00 20 74 65 73 74 2f 62 162:Ok1; . test/b
    00000453  74 2d 62 38 3a 32 37 3a  65 62 3a 34 63 3a 33 63 t-b8:27: eb:4c:3c
    00000463  3a 65 33 2f 73 74 61 74  75 73 63 6f 6e 6e 65 63 :e3/stat usconnec
    00000473  74 65 64 3a 31 39 32 2e  31 36 38 2e 31 2e 35 33 ted:192. 168.1.53
    00000483  3a 4f 6b 31 3b 00 20 74  65 73 74 2f 62 74 2d 62 :Ok1;. t est/bt-b
    00000493  38 3a 32 37 3a 65 62 3a  65 66 3a 32 39 3a 64 30 8:27:eb: ef:29:d0
    000004A3  2f 73 74 61 74 75 73 63  6f 6e 6e 65 63 74 65 64 /statusc onnected
    000004B3  3a 31 39 32 2e 31 36 38  2e 31 2e 39 31 3a 4f 6b :192.168 .1.91:Ok
    000004C3  31 3c 00 20 74 65 73 74  2f 62 74 2d 62 38 3a 32 1<. test /bt-b8:2
    000004D3  37 3a 65 62 3a 64 35 3a  33 36 3a 64 34 2f 73 74 7:eb:d5: 36:d4/st
    000004E3  61 74 75 73 63 6f 6e 6e  65 63 74 65 64 3a 31 39 atusconn ected:19
    000004F3  32 2e 31 36 38 2e 31 2e  31 30 33 3a 4f 6b 31 3c 2.168.1. 103:Ok1<
    00000503  00 20 74 65 73 74 2f 62  74 2d 62 38 3a 32 37 3a . test/b t-b8:27:
    00000513  65 62 3a 38 34 3a 64 63  3a 39 66 2f 73 74 61 74 eb:84:dc :9f/stat
    00000523  75 73 63 6f 6e 6e 65 63  74 65 64 3a 31 39 32 2e usconnec ted:192.
    00000533  31 36 38 2e 31 2e 31 30  34 3a 4f 6b 31 3c 00 20 168.1.10 4:Ok1<. 
    00000543  74 65 73 74 2f 62 74 2d  62 38 3a 32 37 3a 65 62 test/bt- b8:27:eb
    00000553  3a 62 66 3a 33 39 3a 35  30 2f 73 74 61 74 75 73 :bf:39:5 0/status
    00000563  63 6f 6e 6e 65 63 74 65  64 3a 31 39 32 2e 31 36 connecte d:192.16
    00000573  38 2e 31 2e 31 30 32 3a  4f 6b 31 3c 00 20 74 65 8.1.102: Ok1<. te
    00000583  73 74 2f 62 74 2d 62 38  3a 32 37 3a 65 62 3a 62 st/bt-b8 :27:eb:b
    00000593  39 3a 34 63 3a 34 36 2f  73 74 61 74 75 73 63 6f 9:4c:46/ statusco
    000005A3  6e 6e 65 63 74 65 64 3a  31 39 32 2e 31 36 38 2e nnected: 192.168.
    000005B3  31 2e 31 30 31 3a 4f 6b  31 3b 00 20 74 65 73 74 1.101:Ok 1;. test
    000005C3  2f 62 74 2d 62 38 3a 32  37 3a 65 62 3a 31 61 3a /bt-b8:2 7:eb:1a:
    000005D3  62 38 3a 39 64 2f 73 74  61 74 75 73 63 6f 6e 6e b8:9d/st atusconn
    000005E3  65 63 74 65 64 3a 31 39  32 2e 31 36 38 2e 31 2e ected:19 2.168.1.
    000005F3  39 39 3a 4f 6b                                   99:Ok
0000004A  40 02 00 01                                      @...
    000005F8  33 30 00 20 74 65 73 74  2f 62 74 2d 61 32 3a 36 30. test /bt-a2:6
    00000608  64 3a 33 65 3a 34 65 3a  66 34 3a 62 62 2f 73 74 d:3e:4e: f4:bb/st
    00000618  61 74 75 73 00 0e 64 69  73 63 6f 6e 6e 65 63 74 atus..di sconnect
    00000628  65 64 33 30 00 20 74 65  73 74 2f 62 74 2d 62 38 ed30. te st/bt-b8
    00000638  3a 32 37 3a 65 62 3a 66  63 3a 37 33 3a 33 63 2f :27:eb:f c:73:3c/
    00000648  73 74 61 74 75 73 00 0f  64 69 73 63 6f 6e 6e 65 status.. disconne
    00000658  63 74 65 64 33 30 00 20  74 65 73 74 2f 62 74 2d cted30.  test/bt-
    00000668  62 38 3a 32 37 3a 65 62  3a 37 37 3a 61 63 3a 35 b8:27:eb :77:ac:5
    00000678  62 2f 73 74 61 74 75 73  00 10 64 69 73 63 6f 6e b/status ..discon
    00000688  6e 65 63 74 65 64 33 30  00 20 74 65 73 74 2f 62 nected30 . test/b
    00000698  74 2d 62 38 3a 32 37 3a  65 62 3a 32 36 3a 30 63 t-b8:27: eb:26:0c
    000006A8  3a 37 39 2f 73 74 61 74  75 73 00 11 64 69 73 63 :79/stat us..disc
    000006B8  6f 6e 6e 65 63 74 65 64                          onnected 
0000004E  50 02 00 0b 40 02 00 02  40 02 00 03 40 02 00 04 P...@... @...@...
0000005E  40 02 00 05 40 02 00 06  40 02 00 07 40 02 00 08 @...@... @...@...
0000006E  40 02 00 09 40 02 00 0a  40 02 00 0c 40 02 00 0d @...@... @...@...
    000006C0  62 02 00 0b                                      b...
0000007E  40 02 00 0e 40 02 00 0f  40 02 00 10 40 02 00 11 @...@... @...@...
0000008E  70 02 00 0b                                      p...
    000006C4  32 30 00 20 74 65 73 74  2f 62 74 2d 62 38 3a 32 20. test /bt-b8:2
    000006D4  37 3a 65 62 3a 32 32 3a  34 61 3a 36 35 2f 73 74 7:eb:22: 4a:65/st
    000006E4  61 74 75 73 00 12 64 69  73 63 6f 6e 6e 65 63 74 atus..di sconnect
    000006F4  65 64                                            ed
00000092  40 02 00 12                                      @...

It ran for days without problems, but then a client MQTT-SPY v1.0 ran out of memory (could be completely unrelated)

[toast-uz]

I guess it should be treated carefully due to a security issue. Keep in touch if you have any update.

[PierreF]

@edwin-oetelaar The MQTT-SPY that does out-of-memory is it running on the same host as the Mosquitto server ? Said otherwise, is it possible that Mosquitto had memory allocation issue due to low free memory ?
As you say in #629 there seems to be on common point: some FD get closed but they should not (FD=0 and/or 1 in your case, FD=3 for #629).
Are you using Websocket or only plain TCP listenner ?

[edwin-oetelaar]

About websockets enabled : yes
the configuration contains

listener 9001
protocol websockets

[ralight]

Which version of libwebsockets are you using? Is that the full listener/port configuration?

[edwin-oetelaar]

I am running this : https://github.com/toke/docker-mosquitto a docker image without modifications.

The config is here :

pid_file /var/run/mosquitto.pid

persistence true
persistence_location /mqtt/data/

user mosquitto

# Port to use for the default listener.
port 1883


log_dest file /mqtt/log/mosquitto.log
log_dest stdout

listener 9001
protocol websockets

I really have no idea what version of libwebsockets it contains.
I thought it was a quick way to spin up a server... but.
Since this is too much magic and loss of control for me, I will be building my own mosquitto from now on ;-)

[hui6075]

did you configured with bridge? is there any possibilities that some client encountered a duplicate close after it's context has been freed? could you call assert(0) once COMPAT_CLOSE() with sockfd =1 in the code so that we can find the answer from the core file asap since this is a series danger?

[ralight]

That's helpful, it means it is the version of libwebsockets from Debian Jessie which I can get directly.

[ralight]

Some more questions for you - are you actually using websockets clients, and how many clients do you have connected?

[edwin-oetelaar]

I have no websockets connected.
I plan to try that out some more but, about 20 normal mqtt connections, mostly idle.
Some messages are somewhat large, about 3.5MByte, but server is only really working about 1% of the time.
The server is just doing nothing really, just keeping the connections alive 1 byte every 60 seconds.

[ralight]

If you do have websockets clients, I'm concerned we might be seeing a problem in libwebsockets 1.2, which is now ancient and never worked properly for us anyway.