Hello list,
(Please CC me on any replies since I am not subscribed to the list.)
After upgrading to 2.6.31.2 I noticed a strange behaviour with my
/dev/ttySx entries. I tried earlier kernels too and saw the same thing
happening, albeit not as often. So what's the probem?
Short description:
Although I see this in dmesg
serial 00:05: activated
00:05: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
serial 00:06: activated
00:06: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
very often after boot either ttyS0 or ttyS1 is missing under /dev.
I tried to figure out what was happening and did the following.
* stopped udevd
* rmmod 8250_pnp
* rmmod 8250
No more /dev/ttySx entries under dev.
Then I started udevd --debug and loaded 8250.
As a result ttyS[0123] were created. Then I loaded 8250_pnp.
Now here the problem starts (normally after a few rmmod;modprobe cycles).
I removed the 8250_pnp module again and the ttyS entries stayed (I think
because of the 8250 module). Upon re-inserting the 8250_pnp module disappeared vanished.
I think this is part of the relevant udev output
1254937120.013500 [24944] event_queue_delete: seq 10438 done with 0
1254937120.016933 [24944] event_queue_insert: seq 10439 queued, 'remove'
'tty'
1254937120.017101 [24944] udev_monitor_send_device: passed 148 bytes to
monitor 0x813a1f0
1254937120.017245 [25361] worker_new: seq 10439 running
1254937120.017387 [25361] udev_device_read_db: device 0x8149f80 filled
with db symlink data '/dev/ttyS1'
1254937120.017611 [25361] update_link: no reference left, remove
'/dev/char/4:65'
1254937120.018123 [24944] event_queue_insert: seq 10440 queued, 'add'
'tty'
1254937120.018314 [24944] udev_monitor_send_device: passed 136 bytes to
monitor 0x813a1f0
1254937120.018473 [25362] worker_new: seq 10440 running
1254937120.018629 [25362] udev_device_new_from_syspath: device 0x814a048
has devpath '/devices/pnp0/00:06/tty/ttyS1'
1254937120.018763 [25362] udev_rules_apply_to_event: LINK 'char/4:65'
/lib/udev/rules.d/50-udev-default.rules:2
1254937120.018943 [25362] udev_device_new_from_syspath: device 0x813a1f0
has devpath '/devices/pnp0/00:06'
1254937120.019085 [25362] udev_device_new_from_syspath: device 0x814a3d0
has devpath '/devices/pnp0'
1254937120.019207 [25362] udev_rules_apply_to_event: GROUP 20
/lib/udev/rules.d/91-permissions.rules:48
1254937120.019301 [25362] udev_event_execute_rules: no node name set,
will use device name 'ttyS1'
1254937120.019395 [25362] udev_device_update_db: create db link (ttyS1
char/4:65)
1254937120.019476 [25362] udev_node_add: creating device node
'/dev/ttyS1', devnum=4:65, mode=0660, uid=0, gid=20
1254937120.019597 [25362] udev_node_mknod: preserve file '/dev/ttyS1',
because it has correct dev_t
1254937120.019850 [25362] update_link: '/dev/char/4:65' with target
'/dev/ttyS1' has the highest priority 0, create it
1254937120.019994 [25362] node_symlink: preserve already existing
symlink '/dev/char/4:65' to '../ttyS1'
1254937120.020122 [25362] udev_monitor_send_device: passed -1 bytes to
monitor 0x814a8d8
1254937120.020223 [25362] worker_new: seq 10440 processed with 0
1254937120.020375 [24944] event_queue_delete: seq 10440 done with 0
1254937120.020527 [24944] event_queue_insert: seq 10441 queued, 'add'
'drivers'
1254937120.020697 [24944] udev_monitor_send_device: passed 117 bytes to
monitor 0x813a1f0
1254937120.020840 [25362] worker_new: seq 10441 running
1254937120.021093 [25362] udev_monitor_send_device: passed -1 bytes to
monitor 0x814a8d8
1254937120.021212 [25362] worker_new: seq 10441 processed with 0
1254937120.021491 [25361] udev_node_remove: removing device node
'/dev/ttyS1'
1254937120.021695 [25361] udev_monitor_send_device: passed -1 bytes to
monitor 0x8149740
1254937120.021794 [25361] worker_new: seq 10439 processed with 0
1254937120.021941 [24944] event_queue_delete: seq 10441 done with 0
1254937120.022067 [24944] event_queue_delete: seq 10439 done with 0
1254937174.180067 [24944] event_queue_insert: seq 10442 queued, 'add'
'uids'
1254937174.180250 [24944] udev_monitor_send_device: passed 109 bytes to
monitor 0x813a1f0
1254937174.181362 [25361] worker_new: seq 10442 running
1254937174.181645 [25361] udev_monitor_send_device: passed -1 bytes to
monitor 0x8149740
1254937174.182118 [25361] worker_new: seq 10442 processed with 0
1254937174.182249 [24944] event_queue_delete: seq 10442 done with 0
1254937174.217080 [24944] event_queue_insert: seq 10443 queued, 'remove'
'uids'
1254937174.217226 [24944] udev_monitor_send_device: passed 112 bytes to
monitor 0x813a1f0
1254937174.217330 [25361] worker_new: seq 10443 running
1254937174.217466 [25361] udev_monitor_send_device: passed -1 bytes to
monitor 0x8149740
1254937174.217542 [25361] worker_new: seq 10443 processed with 0
1254937174.217647 [24944] event_queue_delete: seq 10443 done with 0
It looks there is a race here. The code sees that ttyS1 is existing and wants to reuse it
but at the same time deletes it. So I end up with either no ttyS0 or
ttyS1. I would not really care if this was just happening during the
rmmod;modprobe shuffle but this also happens fairly often during boot as
well. A headless system is connected via ttyS0 and I have to either
create the entry manually or restart udev to be able to connect to
it. I tried this on 2.6.30.2, 2.6.31 and 2.6.31.2 with the latest udev
from debian and from the git tree.
Kind regards,
Michael
[CC: linux-hotplug aka the udev list]
On 10/7/09, Michael Guntsche <[email protected]> wrote:
> Hello list,
>
> (Please CC me on any replies since I am not subscribed to the list.)
>
> After upgrading to 2.6.31.2 I noticed a strange behaviour with my
> /dev/ttySx entries. I tried earlier kernels too and saw the same thing
> happening, albeit not as often. So what's the probem?
>
> Short description:
> Although I see this in dmesg
> serial 00:05: activated
> 00:05: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
> serial 00:06: activated
> 00:06: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
>
> very often after boot either ttyS0 or ttyS1 is missing under /dev.
> I tried to figure out what was happening and did the following.
>
> * stopped udevd
> * rmmod 8250_pnp
> * rmmod 8250
>
> No more /dev/ttySx entries under dev.
>
> Then I started udevd --debug and loaded 8250.
> As a result ttyS[0123] were created. Then I loaded 8250_pnp.
> Now here the problem starts (normally after a few rmmod;modprobe cycles).
> I removed the 8250_pnp module again and the ttyS entries stayed (I think
> because of the 8250 module). Upon re-inserting the 8250_pnp module
> disappeared vanished.
> I think this is part of the relevant udev output
>
> 1254937120.013500 [24944] event_queue_delete: seq 10438 done with 0
> 1254937120.016933 [24944] event_queue_insert: seq 10439 queued, 'remove'
> 'tty'
> 1254937120.017101 [24944] udev_monitor_send_device: passed 148 bytes to
> monitor 0x813a1f0
> 1254937120.017245 [25361] worker_new: seq 10439 running
> 1254937120.017387 [25361] udev_device_read_db: device 0x8149f80 filled
> with db symlink data '/dev/ttyS1'
> 1254937120.017611 [25361] update_link: no reference left, remove
> '/dev/char/4:65'
> 1254937120.018123 [24944] event_queue_insert: seq 10440 queued, 'add'
> 'tty'
> 1254937120.018314 [24944] udev_monitor_send_device: passed 136 bytes to
> monitor 0x813a1f0
> 1254937120.018473 [25362] worker_new: seq 10440 running
> 1254937120.018629 [25362] udev_device_new_from_syspath: device 0x814a048
> has devpath '/devices/pnp0/00:06/tty/ttyS1'
> 1254937120.018763 [25362] udev_rules_apply_to_event: LINK 'char/4:65'
> /lib/udev/rules.d/50-udev-default.rules:2
> 1254937120.018943 [25362] udev_device_new_from_syspath: device 0x813a1f0
> has devpath '/devices/pnp0/00:06'
> 1254937120.019085 [25362] udev_device_new_from_syspath: device 0x814a3d0
> has devpath '/devices/pnp0'
> 1254937120.019207 [25362] udev_rules_apply_to_event: GROUP 20
> /lib/udev/rules.d/91-permissions.rules:48
> 1254937120.019301 [25362] udev_event_execute_rules: no node name set,
> will use device name 'ttyS1'
> 1254937120.019395 [25362] udev_device_update_db: create db link (ttyS1
> char/4:65)
> 1254937120.019476 [25362] udev_node_add: creating device node
> '/dev/ttyS1', devnum=4:65, mode=0660, uid=0, gid=20
> 1254937120.019597 [25362] udev_node_mknod: preserve file '/dev/ttyS1',
> because it has correct dev_t
> 1254937120.019850 [25362] update_link: '/dev/char/4:65' with target
> '/dev/ttyS1' has the highest priority 0, create it
> 1254937120.019994 [25362] node_symlink: preserve already existing
> symlink '/dev/char/4:65' to '../ttyS1'
> 1254937120.020122 [25362] udev_monitor_send_device: passed -1 bytes to
> monitor 0x814a8d8
> 1254937120.020223 [25362] worker_new: seq 10440 processed with 0
> 1254937120.020375 [24944] event_queue_delete: seq 10440 done with 0
> 1254937120.020527 [24944] event_queue_insert: seq 10441 queued, 'add'
> 'drivers'
> 1254937120.020697 [24944] udev_monitor_send_device: passed 117 bytes to
> monitor 0x813a1f0
> 1254937120.020840 [25362] worker_new: seq 10441 running
> 1254937120.021093 [25362] udev_monitor_send_device: passed -1 bytes to
> monitor 0x814a8d8
> 1254937120.021212 [25362] worker_new: seq 10441 processed with 0
> 1254937120.021491 [25361] udev_node_remove: removing device node
> '/dev/ttyS1'
> 1254937120.021695 [25361] udev_monitor_send_device: passed -1 bytes to
> monitor 0x8149740
> 1254937120.021794 [25361] worker_new: seq 10439 processed with 0
> 1254937120.021941 [24944] event_queue_delete: seq 10441 done with 0
> 1254937120.022067 [24944] event_queue_delete: seq 10439 done with 0
> 1254937174.180067 [24944] event_queue_insert: seq 10442 queued, 'add'
> 'uids'
> 1254937174.180250 [24944] udev_monitor_send_device: passed 109 bytes to
> monitor 0x813a1f0
> 1254937174.181362 [25361] worker_new: seq 10442 running
> 1254937174.181645 [25361] udev_monitor_send_device: passed -1 bytes to
> monitor 0x8149740
> 1254937174.182118 [25361] worker_new: seq 10442 processed with 0
> 1254937174.182249 [24944] event_queue_delete: seq 10442 done with 0
> 1254937174.217080 [24944] event_queue_insert: seq 10443 queued, 'remove'
> 'uids'
> 1254937174.217226 [24944] udev_monitor_send_device: passed 112 bytes to
> monitor 0x813a1f0
> 1254937174.217330 [25361] worker_new: seq 10443 running
> 1254937174.217466 [25361] udev_monitor_send_device: passed -1 bytes to
> monitor 0x8149740
> 1254937174.217542 [25361] worker_new: seq 10443 processed with 0
> 1254937174.217647 [24944] event_queue_delete: seq 10443 done with 0
>
>
> It looks there is a race here. The code sees that ttyS1 is existing and
> wants to reuse it
> but at the same time deletes it. So I end up with either no ttyS0 or
> ttyS1. I would not really care if this was just happening during the
> rmmod;modprobe shuffle but this also happens fairly often during boot as
> well. A headless system is connected via ttyS0 and I have to either
> create the entry manually or restart udev to be able to connect to
> it. I tried this on 2.6.30.2, 2.6.31 and 2.6.31.2 with the latest udev
> from debian and from the git tree.
Good sleuthing.
Udev would have avoided the race prior to
82c785e "udevd: remove check for dev_t, DEVPATH_OLD takes care of that"
(the "check" removed here used to serialize events based on the device
major:minor number).
So - udev probably needs to add the check back.
It might also be the case that future kernels could set DEVPATH_OLD as
suggested. I don't know the gory details of 8250_pnp though.
Thanks
Alan
On Wed, Oct 7, 2009 at 21:46, Alan Jenkins
<[email protected]> wrote:
> Udev would have avoided the race prior to
>
> 82c785e "udevd: remove check for dev_t, DEVPATH_OLD takes care of that"
>
> (the "check" removed here used to serialize events based on the device
> major:minor number).
>
> So - udev probably needs to add the check back.
What are the two devices with the same major/minor but a different DEVPATH?
> It might also be the case that future kernels could set DEVPATH_OLD as
> suggested. I don't know the gory details of 8250_pnp though.
The DEVPATH_OLD is only added when one and the same device was renamed
or moved, which isn't the case here, I guess?
Kay
On Wed, Oct 7, 2009 at 22:06, Kay Sievers <[email protected]> wrote:
> On Wed, Oct 7, 2009 at 21:46, Alan Jenkins
> <[email protected]> wrote:
>> Udev would have avoided the race prior to
>>
>> 82c785e "udevd: remove check for dev_t, DEVPATH_OLD takes care of that"
>>
>> (the "check" removed here used to serialize events based on the device
>> major:minor number).
>>
>> So - udev probably needs to add the check back.
>
> What are the two devices with the same major/minor but a different DEVPATH?
To be more specific, Michael, can you please run "udevadm monitor" at
the same time you see this happen?
>> It might also be the case that future kernels could set DEVPATH_OLD as
>> suggested. I don't know the gory details of 8250_pnp though.
>
> The DEVPATH_OLD is only added when one and the same device was renamed
> or moved, which isn't the case here, I guess?
Thanks,
Kay
On 2009.10.07 22:12:28 , Kay Sievers wrote:
> To be more specific, Michael, can you please run "udevadm monitor" at
> the same time you see this happen?
I started udevadm monitor with the module installed AND all 4 devices
populated. Then I removed the module....
KERNEL[1254947142.220060] remove /devices/pnp0/00:06/tty/ttyS1 (tty)
UDEV [1254947142.220121] add
/devices/platform/serial8250/tty/ttyS1 (tty)
KERNEL[1254947142.220161] add
/devices/platform/serial8250/tty/ttyS1 (tty)
UDEV [1254947142.220857] remove /devices/pnp0/00:06/tty/ttyS1 (tty)
KERNEL[1254947142.223078] remove /devices/pnp0/00:05/tty/ttyS0 (tty)
UDEV [1254947142.223134] add
/devices/platform/serial8250/tty/ttyS0 (tty)
KERNEL[1254947142.223175] add
/devices/platform/serial8250/tty/ttyS0 (tty)
UDEV [1254947142.223800] remove /devices/pnp0/00:05/tty/ttyS0 (tty)
KERNEL[1254947142.225369] remove /bus/pnp/drivers/serial (drivers)
UDEV [1254947142.225419] remove /module/8250_pnp (module)
KERNEL[1254947142.225455] remove /module/8250_pnp (module)
UDEV [1254947142.225675] remove /bus/pnp/drivers/serial (drivers)
Afterwards ONLY ttyS2 and ttS3 were under /dev.
I then added the module again ....
KERNEL[1254947157.330470] add /module/8250_pnp (module)
UDEV [1254947157.330521] add /module/8250_pnp (module)
KERNEL[1254947157.333498] remove
/devices/platform/serial8250/tty/ttyS0 (tty)
KERNEL[1254947157.333550] add /devices/pnp0/00:05/tty/ttyS0 (tty)
UDEV [1254947157.334830] add /devices/pnp0/00:05/tty/ttyS0 (tty)
UDEV [1254947157.334889] remove
/devices/platform/serial8250/tty/ttyS0 (tty)
KERNEL[1254947157.338967] remove
/devices/platform/serial8250/tty/ttyS1 (tty)
KERNEL[1254947157.339020] add /devices/pnp0/00:06/tty/ttyS1 (tty)
KERNEL[1254947157.339056] add /bus/pnp/drivers/serial (drivers)
UDEV [1254947157.340180] remove
/devices/platform/serial8250/tty/ttyS1 (tty)
UDEV [1254947157.340753] add /devices/pnp0/00:06/tty/ttyS1 (tty)
UDEV [1254947157.341202] add /bus/pnp/drivers/serial (drivers)
ONLY ttyS1 (and S2, S3) where there.
Kind regards,
Michael
On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <[email protected]> wrote:
> add /module/8250_pnp (module)
> remove /devices/platform/serial8250/tty/ttyS0 (tty)
> add /devices/pnp0/00:05/tty/ttyS0 (tty)
That's pretty odd, that the loading of a module removes pre-existing
devices created by other code, and creates new ones with the same name
and major/minor.
As Alan mentioned, we could serialize events which carry the the same
major/minor number, that should work around such behavior.
Thanks,
Kay
On Wed, 7 Oct 2009 22:53:12 +0200
Kay Sievers <[email protected]> wrote:
> On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <[email protected]> wrote:
> > add ? ? ?/module/8250_pnp (module)
> > remove /devices/platform/serial8250/tty/ttyS0 (tty)
> > add ? ? ?/devices/pnp0/00:05/tty/ttyS0 (tty)
>
> That's pretty odd, that the loading of a module removes pre-existing
> devices created by other code, and creates new ones with the same name
> and major/minor.
Quite normal. The serial code has always done this.
On Wed, Oct 7, 2009 at 23:10, Alan Cox <[email protected]> wrote:
> On Wed, 7 Oct 2009 22:53:12 +0200
> Kay Sievers <[email protected]> wrote:
>
>> On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <[email protected]> wrote:
>> > add /module/8250_pnp (module)
>> > remove /devices/platform/serial8250/tty/ttyS0 (tty)
>> > add /devices/pnp0/00:05/tty/ttyS0 (tty)
>>
>> That's pretty odd, that the loading of a module removes pre-existing
>> devices created by other code, and creates new ones with the same name
>> and major/minor.
>
> Quite normal. The serial code has always done this.
Heh, I hope you don't tell people to look at floppy.c if they want to see
something "normal". :)
Kay
On Wed, 2009-10-07 at 22:53 +0200, Kay Sievers wrote:
> On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <[email protected]> wrote:
> > add /module/8250_pnp (module)
> > remove /devices/platform/serial8250/tty/ttyS0 (tty)
> > add /devices/pnp0/00:05/tty/ttyS0 (tty)
>
> That's pretty odd, that the loading of a module removes pre-existing
> devices created by other code, and creates new ones with the same name
> and major/minor.
>
> As Alan mentioned, we could serialize events which carry the the same
> major/minor number, that should work around such behavior.
Michael, you mentioned trying the udev git version. Any chance to check
if that fixes it?
Thanks,
Kay
diff --git a/udev/udevd.c b/udev/udevd.c
index 62c6436..dfdbb4c 100644
--- a/udev/udevd.c
+++ b/udev/udevd.c
@@ -118,6 +118,8 @@ struct event {
const char *devpath;
size_t devpath_len;
const char *devpath_old;
+ dev_t devnum;
+ bool is_block;
};
static struct event *node_to_event(struct udev_list_node *node)
@@ -410,6 +412,8 @@ static void event_queue_insert(struct udev_device *dev)
event->devpath = udev_device_get_devpath(dev);
event->devpath_len = strlen(event->devpath);
event->devpath_old = udev_device_get_devpath_old(dev);
+ event->devnum = udev_device_get_devnum(dev);
+ event->is_block = (strcmp("block", udev_device_get_subsystem(dev)) == 0);
udev_queue_export_device_queued(udev_queue_export, dev);
info(event->udev, "seq %llu queued, '%s' '%s'\n", udev_device_get_seqnum(dev),
@@ -473,7 +477,7 @@ static int mem_size_mb(void)
}
/* lookup event for identical, parent, child device */
-static int devpath_busy(struct event *event)
+static bool is_devpath_busy(struct event *event)
{
struct udev_list_node *loop;
size_t common;
@@ -488,18 +492,21 @@ static int devpath_busy(struct event *event)
/* event we checked earlier still exists, no need to check again */
if (loop_event->seqnum == event->delaying_seqnum)
- return 2;
+ return true;
/* found ourself, no later event can block us */
if (loop_event->seqnum >= event->seqnum)
break;
+ /* check major/minor */
+ if (major(event->devnum) != 0 && event->devnum == loop_event->devnum && event->is_block == loop_event->is_block)
+ return true;
+
/* check our old name */
- if (event->devpath_old != NULL)
- if (strcmp(loop_event->devpath, event->devpath_old) == 0) {
- event->delaying_seqnum = loop_event->seqnum;
- return 3;
- }
+ if (event->devpath_old != NULL && strcmp(loop_event->devpath, event->devpath_old) == 0) {
+ event->delaying_seqnum = loop_event->seqnum;
+ return true;
+ }
/* compare devpath */
common = MIN(loop_event->devpath_len, event->devpath_len);
@@ -511,26 +518,26 @@ static int devpath_busy(struct event *event)
/* identical device event found */
if (loop_event->devpath_len == event->devpath_len) {
event->delaying_seqnum = loop_event->seqnum;
- return 4;
+ return true;
}
/* parent device event found */
if (event->devpath[common] == '/') {
event->delaying_seqnum = loop_event->seqnum;
- return 5;
+ return true;
}
/* child device event found */
if (loop_event->devpath[common] == '/') {
event->delaying_seqnum = loop_event->seqnum;
- return 6;
+ return true;
}
/* no matching device */
continue;
}
- return 0;
+ return false;
}
static void events_start(struct udev *udev)
@@ -544,7 +551,7 @@ static void events_start(struct udev *udev)
continue;
/* do not start event if parent or child event is still running */
- if (devpath_busy(event) != 0) {
+ if (is_devpath_busy(event)) {
dbg(udev, "delay seq %llu (%s)\n", event->seqnum, event->devpath);
continue;
}
On 2009.10.07 23:23:22 , Kay Sievers wrote:
> Michael, you mentioned trying the udev git version. Any chance to check
> if that fixes it?
>
> Thanks,
> Kay
>
<snip>
I applied it to current git and gave it a quick spin with.
rmmod 8250_pnp;sleep 1;ls -la /dev/ttyS*;modprobe 8250_pnp;sleep 1;ls
-la /dev/ttyS*
I was not able to reproduce the problem even after 30 runs.
I will let it run some more just to be sure but so far it looks good.
Michael
On Wed, Oct 7, 2009 at 23:52, Michael Guntsche <[email protected]> wrote:
> On 2009.10.07 23:23:22 , Kay Sievers wrote:
>> Michael, you mentioned trying the udev git version. Any chance to check
>> if that fixes it?
>
> I applied it to current git and gave it a quick spin with.
>
> rmmod 8250_pnp;sleep 1;ls -la /dev/ttyS*;modprobe 8250_pnp;sleep 1;ls
> -la /dev/ttyS*
>
> I was not able to reproduce the problem even after 30 runs.
> I will let it run some more just to be sure but so far it looks good.
Thanks for the tests. It's in git now.
Kay