Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Alan Jenkins]

[CC: linux-hotplug aka the udev list]

On 10/7/09, Michael Guntsche <mike@it-loops.com> 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\x0660, uid=0, gid 
> 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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Kay Sievers]

On Wed, Oct 7, 2009 at 21:46, Alan Jenkins
<sourcejedi.lkml@googlemail.com> 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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Kay Sievers]

On Wed, Oct 7, 2009 at 22:06, Kay Sievers <kay.sievers@vrfy.org> wrote:
> On Wed, Oct 7, 2009 at 21:46, Alan Jenkins
> <sourcejedi.lkml@googlemail.com> 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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Michael Guntsche]

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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Kay Sievers]

On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <mike@it-loops.com> 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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Alan Cox]

On Wed, 7 Oct 2009 22:53:12 +0200
Kay Sievers <kay.sievers@vrfy.org> wrote:

> On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <mike@it-loops.com> 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.

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Kay Sievers]

On Wed, Oct 7, 2009 at 23:10, Alan Cox <alan@lxorguk.ukuu.org.uk> wrote:
> On Wed, 7 Oct 2009 22:53:12 +0200
> Kay Sievers <kay.sievers@vrfy.org> wrote:
>
>> On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <mike@it-loops.com> 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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Kay Sievers]

On Wed, 2009-10-07 at 22:53 +0200, Kay Sievers wrote:
> On Wed, Oct 7, 2009 at 22:31, Michael Guntsche <mike@it-loops.com> 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;
 		}

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Michael Guntsche]

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

Re: [BUG] No ttyS0 - Strange udev 8250_pnp interaction

[Kay Sievers]

On Wed, Oct 7, 2009 at 23:52, Michael Guntsche <mike@it-loops.com> 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