From: Paul Bolle <hidden> Date: 2016-02-03 16:16:37
On wo, 2016-02-03 at 16:31 +0100, Dmitry Vyukov wrote:
The following program causes a memory leak of ser_cardstate object
allocated in gigaset_initcshw:
// autogenerated by syzkaller (http://github.com/google/syzkaller)
#include <pthread.h>
#include <stdint.h>
#include <string.h>
#include <sys/syscall.h>
#include <unistd.h>
int main()
{
long r[7];
memset(r, -1, sizeof(r));
r[0] = syscall(SYS_mmap, 0x20000000ul, 0x10000ul, 0x3ul, 0x32ul,
0xfffffffffffffffful, 0x0ul);
r[2] = syscall(SYS_open, "/dev/ptmx", 0x8002ul, 0x0ul, 0, 0, 0);
*(uint32_t*)0x20002b1e = (uint32_t)0x10;
r[4] = syscall(SYS_ioctl, r[2], 0x5423ul, 0x20002b1eul, 0, 0, 0);
*(uint32_t*)0x20009000 = (uint32_t)0x7;
r[6] = syscall(SYS_ioctl, r[2], 0x5423ul, 0x20009000ul, 0, 0, 0);
strace translated this for me to
mmap(0x20000000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x20000000
open("/dev/ptmx", O_RDWR|O_LARGEFILE) = 3
ioctl(3, TIOCSETD, [16]) = 0
ioctl(3, TIOCSETD, [7]) = 0
Where 16 is N_GIGASET_M101, while 7 is N_6PACK.
From: Paul Bolle <hidden> Date: 2016-02-03 19:11:11
Hi Dmitry,
On wo, 2016-02-03 at 17:16 +0100, Paul Bolle wrote:
The above should provide me with enough information to figure out
what's going on here.
I've instrumented ser_gigaset with some printk's. Basically I added the
stuff pasted at the end of this message. In 10.000 runs of the program
syzkaller generated the added printk's suggest that struct ser_cardstate
is freed every time.
(Note that this was done on a machine that, probably like the VM
syzkaller was running in, doesn't have the clunky hardware that this
driver manages attached.)
Before I dive deeper into this: can you reproduce this leak? Is it
perhaps a one in gazillion runs thing? Do you have the logs of a run
that warned about this leak at hand?
Thanks,
Paul Bolle
On Wed, Feb 3, 2016 at 8:11 PM, Paul Bolle [off-list ref] wrote:
quoted hunk
Hi Dmitry,
On wo, 2016-02-03 at 17:16 +0100, Paul Bolle wrote:
quoted
The above should provide me with enough information to figure out
what's going on here.
I've instrumented ser_gigaset with some printk's. Basically I added the
stuff pasted at the end of this message. In 10.000 runs of the program
syzkaller generated the added printk's suggest that struct ser_cardstate
is freed every time.
(Note that this was done on a machine that, probably like the VM
syzkaller was running in, doesn't have the clunky hardware that this
driver manages attached.)
Before I dive deeper into this: can you reproduce this leak? Is it
perhaps a one in gazillion runs thing? Do you have the logs of a run
that warned about this leak at hand?
Thanks,
Paul Bolle
(gcc complained about "running" being used uninitialized, though a few
mock runs suggest it got initialized to 0 anyhow. I initialized
"running" to 0 explicitly for the real runs.)
for (;;) {
while (running < 32) {
if (fork() == 0) {
work();
exit(0);
}
running++;
}
if (wait(&status) > 0)
running--;
}
}
(Note to self: this hammers my laptop with about 2.000 runs per second.
After some time systemd's logging appears to have trouble handling the
output this reproducer generates, so maybe messages end up getting
dropped.)
While running it, sample/proc/slabinfo with:
# cat /proc/slabinfo | egrep "^kmalloc-2048"
It constantly grows.
I don't really know how /proc/slabinfo should be interpreted, sorry. But
the interesting fields appear to be "<active_objs>" and "<num_objs>".
"<num_objs>" seems to be stable here (during the runs of a few minutes
that I dare to inflict on my laptop). "<active_objs>" is more volatile.
But I also saw it going down while the reproducer was running.
What are you seeing here?
Thanks,
Paul Bolle
(gcc complained about "running" being used uninitialized, though a few
mock runs suggest it got initialized to 0 anyhow. I initialized
"running" to 0 explicitly for the real runs.)
quoted
for (;;) {
while (running < 32) {
if (fork() == 0) {
work();
exit(0);
}
running++;
}
if (wait(&status) > 0)
running--;
}
}
(Note to self: this hammers my laptop with about 2.000 runs per second.
After some time systemd's logging appears to have trouble handling the
output this reproducer generates, so maybe messages end up getting
dropped.)
quoted
While running it, sample/proc/slabinfo with:
# cat /proc/slabinfo | egrep "^kmalloc-2048"
It constantly grows.
I don't really know how /proc/slabinfo should be interpreted, sorry. But
the interesting fields appear to be "<active_objs>" and "<num_objs>".
"<num_objs>" seems to be stable here (during the runs of a few minutes
that I dare to inflict on my laptop). "<active_objs>" is more volatile.
But I also saw it going down while the reproducer was running.
What are you seeing here?
I see that active_objs is slowly, constantly growing.
I've attached my config file, please try with it. You mentioned that
"16 is N_GIGASET_M101, while 7 is N_6PACK", probably one of these ttys
is not enabled in your config, and so the reproducer is not doing
anything useful.
From: Paul Bolle <hidden> Date: 2016-02-04 13:46:52
Hi Dmitry,
On do, 2016-02-04 at 14:15 +0100, Dmitry Vyukov wrote:
On Thu, Feb 4, 2016 at 2:09 PM, Paul Bolle [off-list ref] wrote:
quoted
What are you seeing here?
I see that active_objs is slowly, constantly growing.
I've attached my config file, please try with it. You mentioned that
"16 is N_GIGASET_M101, while 7 is N_6PACK", probably one of these ttys
is not enabled in your config,
Both are. (A 6pack module is loaded when I run the reproducer. I have no
idea what 6pack is good for. ser_gigaset is familiar, to me.)
and so the reproducer is not doing
anything useful.
I actually wonder whether N_6PACK is relevant. Do you also see this
issue with another line discipline in the second TIOCSETD ioctl?
Maybe it even triggers with two totally different line disciplines in
both calls? A (slightly edited) copy of tty.h is pasted below. It lists
the useful values for the TIOCSETD ioctl.
Would you mind testing a few combinations?
Thanks,
Paul Bolle
/* line disciplines */
#define N_TTY 0
#define N_SLIP 1
#define N_MOUSE 2
#define N_PPP 3
/* 4 is obsolete */
#define N_AX25 5
#define N_X25 6 /* X.25 async */
#define N_6PACK 7
/* 8 is obsolete */
#define N_R3964 9 /* Simatic R3964 */
/* 10 is obsolete */
#define N_IRDA 11 /* Linux IrDa - http://irda.sourceforge.net/ */
/* 12 is obsolete */
#define N_HDLC 13 /* synchronous HDLC */
#define N_SYNC_PPP 14 /* synchronous PPP */
#define N_HCI 15 /* Bluetooth HCI UART */
#define N_GIGASET_M101 16 /* Siemens Gigaset M101 serial DECT adapter */
#define N_SLCAN 17 /* Serial / USB serial CAN Adaptors */
#define N_PPS 18 /* Pulse per Second */
#define N_V253 19 /* Codec control over voice modem */
#define N_CAIF 20 /* CAIF protocol for talking to modems */
#define N_GSM0710 21 /* GSM 0710 Mux */
#define N_TI_WL 22 /* for TI's WL BT, FM, GPS combo chips */
#define N_TRACESINK 23 /* Trace data routing for MIPI P1149.7 */
#define N_TRACEROUTER 24 /* Trace data routing for MIPI P1149.7 */
#define N_NCI 25 /* NFC NCI UART */
On Thu, Feb 4, 2016 at 2:46 PM, Paul Bolle [off-list ref] wrote:
Hi Dmitry,
On do, 2016-02-04 at 14:15 +0100, Dmitry Vyukov wrote:
quoted
On Thu, Feb 4, 2016 at 2:09 PM, Paul Bolle [off-list ref] wrote:
quoted
What are you seeing here?
I see that active_objs is slowly, constantly growing.
I've attached my config file, please try with it. You mentioned that
"16 is N_GIGASET_M101, while 7 is N_6PACK", probably one of these ttys
is not enabled in your config,
Both are. (A 6pack module is loaded when I run the reproducer. I have no
idea what 6pack is good for. ser_gigaset is familiar, to me.)
quoted
and so the reproducer is not doing
anything useful.
I actually wonder whether N_6PACK is relevant. Do you also see this
issue with another line discipline in the second TIOCSETD ioctl?
Maybe it even triggers with two totally different line disciplines in
both calls? A (slightly edited) copy of tty.h is pasted below. It lists
the useful values for the TIOCSETD ioctl.
Would you mind testing a few combinations?
Thanks,
Paul Bolle
/* line disciplines */
#define N_TTY 0
#define N_SLIP 1
#define N_MOUSE 2
#define N_PPP 3
/* 4 is obsolete */
#define N_AX25 5
#define N_X25 6 /* X.25 async */
#define N_6PACK 7
/* 8 is obsolete */
#define N_R3964 9 /* Simatic R3964 */
/* 10 is obsolete */
#define N_IRDA 11 /* Linux IrDa - http://irda.sourceforge.net/ */
/* 12 is obsolete */
#define N_HDLC 13 /* synchronous HDLC */
#define N_SYNC_PPP 14 /* synchronous PPP */
#define N_HCI 15 /* Bluetooth HCI UART */
#define N_GIGASET_M101 16 /* Siemens Gigaset M101 serial DECT adapter */
#define N_SLCAN 17 /* Serial / USB serial CAN Adaptors */
#define N_PPS 18 /* Pulse per Second */
#define N_V253 19 /* Codec control over voice modem */
#define N_CAIF 20 /* CAIF protocol for talking to modems */
#define N_GSM0710 21 /* GSM 0710 Mux */
#define N_TI_WL 22 /* for TI's WL BT, FM, GPS combo chips */
#define N_TRACESINK 23 /* Trace data routing for MIPI P1149.7 */
#define N_TRACEROUTER 24 /* Trace data routing for MIPI P1149.7 */
#define N_NCI 25 /* NFC NCI UART */
One TIOCSETD is enough to trigger the leak.
I've tested with different line disciplines and only N_GIGASET_M101
triggers the leak.
The program prints:
ioctl failed with 19
ioctl failed with 19
ioctl failed with 19
ioctl failed with 19
ioctl failed with 19
ioctl failed with 19
ioctl failed with 19
ioctl failed with 19
And console output looks as follows:
[ 107.311623] driver: 'ser_gigaset': driver_bound: bound to device
'ser_gigaset.0'
[ 107.312502] bus: 'platform': really_probe: bound device
ser_gigaset.0 to driver ser_gigaset
[ 107.313789] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.314335] gigaset: maximum number of devices exceeded
[ 107.318272] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.318794] gigaset: maximum number of devices exceeded
[ 107.319541] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.320072] gigaset: maximum number of devices exceeded
[ 107.320792] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.321834] gigaset: maximum number of devices exceeded
[ 107.322782] kcapi: controller [001] "ser_gigaset" ready.
[ 107.324414] kcapi: controller [001] down.
[ 107.327864] bus: 'platform': remove device ser_gigaset.0
[ 107.328733] kcapi: controller [001]: ser_gigaset unregistered
[ 107.331246] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.331934] kcapi: controller [001]: ser_gigaset attached
[ 107.337741] Registering platform device 'ser_gigaset.0'. Parent at platform
[ 107.340149] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.340664] gigaset: maximum number of devices exceeded
[ 107.341470] bus: 'platform': add device ser_gigaset.0
[ 107.342189] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.342702] gigaset: maximum number of devices exceeded
[ 107.344661] bus: 'platform': driver_probe_device: matched device
ser_gigaset.0 with driver ser_gigaset
[ 107.345420] bus: 'platform': really_probe: probing driver
ser_gigaset with device ser_gigaset.0
[ 107.346185] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.346187] gigaset: maximum number of devices exceeded
[ 107.351893] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.352888] gigaset: maximum number of devices exceeded
[ 107.359171] devices_kset: Moving ser_gigaset.0 to end of list
[ 107.359867] driver: 'ser_gigaset': driver_bound: bound to device
'ser_gigaset.0'
[ 107.366296] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.366794] gigaset: maximum number of devices exceeded
[ 107.367198] ser_gigaset: Serial Driver for Gigaset 307x using Siemens M101
[ 107.367778] gigaset: maximum number of devices exceeded
[ 107.391643] bus: 'platform': really_probe: bound device
ser_gigaset.0 to driver ser_gigaset
[ 107.402270] kcapi: controller [001] "ser_gigaset" ready.
[ 107.404980] kcapi: controller [001] down.
[ 107.407644] bus: 'platform': remove device ser_gigaset.0
[ 107.408554] kcapi: controller [001]: ser_gigaset unregistered
Here is updated program:
// autogenerated by syzkaller (http://github.com/google/syzkaller)
#include <stdint.h>
#include <stdlib.h>
#include <stdio.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/wait.h>
#include <sys/ioctl.h>
#include <fcntl.h>
#include <errno.h>
int r;
void work()
{
int fd;
fd = open("/dev/ptmx", O_RDWR);
if (fd == -1)
exit(printf("open failed with %d\n", errno));
if (ioctl(fd, TIOCSETD, &r))
exit(printf("ioctl failed with %d\n", errno));
}
int main(int argc, char **argv) {
int running, status;
if (argc != 2)
return;
r = atoi(argv[1]);
running = 0;
for (;;) {
while (running < 32) {
if (fork() == 0) {
work();
exit(0);
}
running++;
}
if (wait(&status) > 0)
running--;
}
}
From: Paul Bolle <hidden> Date: 2016-02-04 15:06:20
On do, 2016-02-04 at 15:54 +0100, Dmitry Vyukov wrote:
One TIOCSETD is enough to trigger the leak.
I've tested with different line disciplines and only N_GIGASET_M101
triggers the leak.
So things appear to be just on my plate now. I'll see what I can come up
with. Feel free to prod me if I stay silent for too long.
Thanks for narrowing things down!
Paul Bolle
On Thu, Feb 4, 2016 at 4:06 PM, Paul Bolle [off-list ref] wrote:
On do, 2016-02-04 at 15:54 +0100, Dmitry Vyukov wrote:
quoted
One TIOCSETD is enough to trigger the leak.
I've tested with different line disciplines and only N_GIGASET_M101
triggers the leak.
So things appear to be just on my plate now. I'll see what I can come up
with. Feel free to prod me if I stay silent for too long.
Thanks for narrowing things down!
quoted hunk
0) It's way too late here. And I can't really reproduce, and too many
things jumps to 100% when running your reproducer. Anyhow, this is all I
came up with (for drivers/isdn/gigaset/common.c):
1) On my side the logs do seem more sensible, for what it's worth. But
does this fix the leak?
2) Note that I fear your reproducer allows to DOS the box (even if the
leak turns out to be fixed) so the mess might be getting much worse. I
need a clear hear to think this through. Ie, I need some sleep.
No, it does not help.
I wonder why you don't see the leak I am seeing... are you suing qemu
or real hardware? I am using qemu.
I've added the following change:
@@ -396,6 +396,7 @@ static int gigaset_initcshw(struct cardstate *cs)pr_err("out of memory\n");return-ENOMEM;}+WARN_ON(cs->hw.ser!=NULL);cs->hw.ser=scs;cs->hw.ser->dev.name=GIGASET_MODULENAME;
and it does fire.
Can it be a case that free_cs() runs before gigaset_device_release()?
If that would happen, then cs can be reused while the previous
cs->hw.ser is not freed yet. Just a guess.
From: Paul Bolle <hidden> Date: 2016-02-05 16:06:34
Hi Dmitry,
(If anyone is confused by this conversation: Dmitry replied to an off
list message.)
On vr, 2016-02-05 at 14:28 +0100, Dmitry Vyukov wrote:
I wonder why you don't see the leak I am seeing...
So do I, for a few days now.
are you suing qemu or real hardware? I am using qemu.
Real hardware (a ThinkPad). Probably less powerful that your VM.
What is the rate you're seeing leakage of a struct ser_cardstate? I'm
running your latest test at about 2.000 TIOCSETD's per second - which is
by itself not very useful for our driver - and notice no _obvious_
leakage when I do that for a few minutes. I do note the hardware
screaming to just keep up with the abuse, though.
@@ -396,6 +396,7 @@ static int gigaset_initcshw(struct cardstate *cs)pr_err("out of memory\n");return-ENOMEM;}+WARN_ON(cs->hw.ser!=NULL);cs->hw.ser=scs;cs->hw.ser->dev.name=GIGASET_MODULENAME;
and it does fire.
Can it be a case that free_cs() runs before gigaset_device_release()?
gigaset_device_release() is the release operation that is run when our
struct device goes away. The core code is responsible for calling it, we
can't be certain when that will happen. At least, we should not expect
it to happen directly after calling platform_device_unregister().
(It was actually syzkaller that warned us that we did just that until
recently. See commit 4c5e354a9742 ("ser_gigaset: fix deallocation of
platform device structure").)
If that would happen, then cs can be reused while the previous
cs->hw.ser is not freed yet. Just a guess.
I'll have to ponder on that a bit, sorry.
Paul Bolle
From: Paul Bolle <hidden> Date: 2016-02-11 22:54:20
Hi Dmitry,
On vr, 2016-02-05 at 17:06 +0100, Paul Bolle wrote:
On vr, 2016-02-05 at 14:28 +0100, Dmitry Vyukov wrote:
quoted
I wonder why you don't see the leak I am seeing...
So do I, for a few days now.
0) I finally managed to reliably trigger this leak on an i686, single
core machine (yet another ThinkPad).
1) Note that on that machine the leak was noticeable under the kmalloc
-512 line (struct ser_cardstate is 456 bytes on that machine). I'm
_guessing_ the kmalloc-2048 line, which I stared at for quite some time,
is only relevant here for x86_64 and when there's a bit of
instrumentation, or whatever, added to the slab objects (as they are in
your VM?).
2) More important was that this i686 machine ran a tree that actually
included the offending commit:
25cad69f21f5 ("base/platform: Fix platform drivers with no probe callback").
See, after staring at the gigaset code for way too long I decided to
just use brute force. Ie, I bisected this issue.
2) Anyhow, thanks again for the report. Now on to the next question: how
on earth does that commit make ser_gigaset leak struct ser_cardstate?
To be continued,
Paul Bolle