PCI: Race condition in pci_create_sysfs_dev_files

PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

Hello Bjorn!

I see following error message in dmesg which looks like a race condition:

sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'

I looked at it deeper and found out that in PCI subsystem code is race
condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
of these functions calls pci_create_sysfs_dev_files() and calling this
function more times for same pci device throws above error message.

There can be two different race conditions:

1. pci_bus_add_device() called pcibios_bus_add_device() or
pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
was called for newly registered device. In this case function
pci_create_sysfs_dev_files() is called two times, ones from
pci_bus_add_device() and once from pci_sysfs_init().

2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
which unblock calling pci_create_sysfs_dev_files(). Then another bus
registers new PCI device and calls pci_bus_add_device() which calls
pci_create_sysfs_dev_files() and registers sysfs files. Function
pci_sysfs_init() continues execution and calls function
pci_create_sysfs_dev_files() also for this newly registered device. So
pci_create_sysfs_dev_files() is again called two times.


I workaround both race conditions I created following hack patch. After
applying it I'm not getting that 'sysfs: cannot create duplicate filename'
error message anymore.

Can you look at it how to fix both race conditions in proper way?


diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
index 8e40b3e6da77..691be2258c4e 100644
--- a/drivers/pci/bus.c
+++ b/drivers/pci/bus.c
@@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
 	 */
 	pcibios_bus_add_device(dev);
 	pci_fixup_device(pci_fixup_final, dev);
-	pci_create_sysfs_dev_files(dev);
+	pci_create_sysfs_dev_files(dev, false);
 	pci_proc_attach_device(dev);
 	pci_bridge_d3_update(dev);
 
diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
index 6d78df981d41..b0c4852a51dd 100644
--- a/drivers/pci/pci-sysfs.c
+++ b/drivers/pci/pci-sysfs.c
@@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
 	return retval;
 }
 
-int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
+int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
 {
 	int retval;
 	int rom_size;
 	struct bin_attribute *attr;
 
-	if (!sysfs_initialized)
+	if (!sysfs_initializing && !sysfs_initialized)
 		return -EACCES;
 
 	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
@@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
 static int __init pci_sysfs_init(void)
 {
 	struct pci_dev *pdev = NULL;
-	int retval;
+	int retval = 0;
 
-	sysfs_initialized = 1;
 	for_each_pci_dev(pdev) {
-		retval = pci_create_sysfs_dev_files(pdev);
+		if (!pci_dev_is_added(pdev))
+			continue;
+		retval = pci_create_sysfs_dev_files(pdev, true);
 		if (retval) {
 			pci_dev_put(pdev);
-			return retval;
+			goto out;
 		}
 	}
 
-	return 0;
+out:
+	sysfs_initialized = 1;
+	return retval;
 }
 late_initcall(pci_sysfs_init);
 
diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
index 6d3f75867106..304294c7171e 100644
--- a/drivers/pci/pci.h
+++ b/drivers/pci/pci.h
@@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
 
 /* Functions internal to the PCI core code */
 
-int pci_create_sysfs_dev_files(struct pci_dev *pdev);
+int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
 void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
 #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
 static inline void pci_create_firmware_label_files(struct pci_dev *pdev)

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

Hello! I would like to remind this issue which I reported month ago.

On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> Hello Bjorn!
> 
> I see following error message in dmesg which looks like a race condition:
> 
> sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> 
> I looked at it deeper and found out that in PCI subsystem code is race
> condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> of these functions calls pci_create_sysfs_dev_files() and calling this
> function more times for same pci device throws above error message.
> 
> There can be two different race conditions:
> 
> 1. pci_bus_add_device() called pcibios_bus_add_device() or
> pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> was called for newly registered device. In this case function
> pci_create_sysfs_dev_files() is called two times, ones from
> pci_bus_add_device() and once from pci_sysfs_init().
> 
> 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> which unblock calling pci_create_sysfs_dev_files(). Then another bus
> registers new PCI device and calls pci_bus_add_device() which calls
> pci_create_sysfs_dev_files() and registers sysfs files. Function
> pci_sysfs_init() continues execution and calls function
> pci_create_sysfs_dev_files() also for this newly registered device. So
> pci_create_sysfs_dev_files() is again called two times.
> 
> 
> I workaround both race conditions I created following hack patch. After
> applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> error message anymore.
> 
> Can you look at it how to fix both race conditions in proper way?

Is this workaround diff enough? Or are you going to prepare something better?

Please let me know if I should send this diff as regular patch.

> 
> diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
> index 8e40b3e6da77..691be2258c4e 100644
> --- a/drivers/pci/bus.c
> +++ b/drivers/pci/bus.c
> @@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
>  	 */
>  	pcibios_bus_add_device(dev);
>  	pci_fixup_device(pci_fixup_final, dev);
> -	pci_create_sysfs_dev_files(dev);
> +	pci_create_sysfs_dev_files(dev, false);
>  	pci_proc_attach_device(dev);
>  	pci_bridge_d3_update(dev);
>  
> diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
> index 6d78df981d41..b0c4852a51dd 100644
> --- a/drivers/pci/pci-sysfs.c
> +++ b/drivers/pci/pci-sysfs.c
> @@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
>  	return retval;
>  }
>  
> -int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
> +int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
>  {
>  	int retval;
>  	int rom_size;
>  	struct bin_attribute *attr;
>  
> -	if (!sysfs_initialized)
> +	if (!sysfs_initializing && !sysfs_initialized)
>  		return -EACCES;
>  
>  	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
> @@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
>  static int __init pci_sysfs_init(void)
>  {
>  	struct pci_dev *pdev = NULL;
> -	int retval;
> +	int retval = 0;
>  
> -	sysfs_initialized = 1;
>  	for_each_pci_dev(pdev) {
> -		retval = pci_create_sysfs_dev_files(pdev);
> +		if (!pci_dev_is_added(pdev))
> +			continue;
> +		retval = pci_create_sysfs_dev_files(pdev, true);
>  		if (retval) {
>  			pci_dev_put(pdev);
> -			return retval;
> +			goto out;
>  		}
>  	}
>  
> -	return 0;
> +out:
> +	sysfs_initialized = 1;
> +	return retval;
>  }
>  late_initcall(pci_sysfs_init);
>  
> diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
> index 6d3f75867106..304294c7171e 100644
> --- a/drivers/pci/pci.h
> +++ b/drivers/pci/pci.h
> @@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
>  
>  /* Functions internal to the PCI core code */
>  
> -int pci_create_sysfs_dev_files(struct pci_dev *pdev);
> +int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
>  void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
>  #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
>  static inline void pci_create_firmware_label_files(struct pci_dev *pdev)
> 

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

Hello! I'm adding more people to loop.

Can somebody look at these race conditions and my patch?

On Friday 14 August 2020 10:08:24 Pali Rohár wrote:
> Hello! I would like to remind this issue which I reported month ago.
> 
> On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> > Hello Bjorn!
> > 
> > I see following error message in dmesg which looks like a race condition:
> > 
> > sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> > 
> > I looked at it deeper and found out that in PCI subsystem code is race
> > condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> > of these functions calls pci_create_sysfs_dev_files() and calling this
> > function more times for same pci device throws above error message.
> > 
> > There can be two different race conditions:
> > 
> > 1. pci_bus_add_device() called pcibios_bus_add_device() or
> > pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> > Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> > was called for newly registered device. In this case function
> > pci_create_sysfs_dev_files() is called two times, ones from
> > pci_bus_add_device() and once from pci_sysfs_init().
> > 
> > 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> > which unblock calling pci_create_sysfs_dev_files(). Then another bus
> > registers new PCI device and calls pci_bus_add_device() which calls
> > pci_create_sysfs_dev_files() and registers sysfs files. Function
> > pci_sysfs_init() continues execution and calls function
> > pci_create_sysfs_dev_files() also for this newly registered device. So
> > pci_create_sysfs_dev_files() is again called two times.
> > 
> > 
> > I workaround both race conditions I created following hack patch. After
> > applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> > error message anymore.
> > 
> > Can you look at it how to fix both race conditions in proper way?
> 
> Is this workaround diff enough? Or are you going to prepare something better?
> 
> Please let me know if I should send this diff as regular patch.
> 
> > 
> > diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
> > index 8e40b3e6da77..691be2258c4e 100644
> > --- a/drivers/pci/bus.c
> > +++ b/drivers/pci/bus.c
> > @@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
> >  	 */
> >  	pcibios_bus_add_device(dev);
> >  	pci_fixup_device(pci_fixup_final, dev);
> > -	pci_create_sysfs_dev_files(dev);
> > +	pci_create_sysfs_dev_files(dev, false);
> >  	pci_proc_attach_device(dev);
> >  	pci_bridge_d3_update(dev);
> >  
> > diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
> > index 6d78df981d41..b0c4852a51dd 100644
> > --- a/drivers/pci/pci-sysfs.c
> > +++ b/drivers/pci/pci-sysfs.c
> > @@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
> >  	return retval;
> >  }
> >  
> > -int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
> > +int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
> >  {
> >  	int retval;
> >  	int rom_size;
> >  	struct bin_attribute *attr;
> >  
> > -	if (!sysfs_initialized)
> > +	if (!sysfs_initializing && !sysfs_initialized)
> >  		return -EACCES;
> >  
> >  	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
> > @@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
> >  static int __init pci_sysfs_init(void)
> >  {
> >  	struct pci_dev *pdev = NULL;
> > -	int retval;
> > +	int retval = 0;
> >  
> > -	sysfs_initialized = 1;
> >  	for_each_pci_dev(pdev) {
> > -		retval = pci_create_sysfs_dev_files(pdev);
> > +		if (!pci_dev_is_added(pdev))
> > +			continue;
> > +		retval = pci_create_sysfs_dev_files(pdev, true);
> >  		if (retval) {
> >  			pci_dev_put(pdev);
> > -			return retval;
> > +			goto out;
> >  		}
> >  	}
> >  
> > -	return 0;
> > +out:
> > +	sysfs_initialized = 1;
> > +	return retval;
> >  }
> >  late_initcall(pci_sysfs_init);
> >  
> > diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
> > index 6d3f75867106..304294c7171e 100644
> > --- a/drivers/pci/pci.h
> > +++ b/drivers/pci/pci.h
> > @@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
> >  
> >  /* Functions internal to the PCI core code */
> >  
> > -int pci_create_sysfs_dev_files(struct pci_dev *pdev);
> > +int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
> >  void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
> >  #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
> >  static inline void pci_create_firmware_label_files(struct pci_dev *pdev)
> > 

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

PING?

On Wednesday 09 September 2020 13:28:50 Pali Rohár wrote:
> Hello! I'm adding more people to loop.
> 
> Can somebody look at these race conditions and my patch?
> 
> On Friday 14 August 2020 10:08:24 Pali Rohár wrote:
> > Hello! I would like to remind this issue which I reported month ago.
> > 
> > On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> > > Hello Bjorn!
> > > 
> > > I see following error message in dmesg which looks like a race condition:
> > > 
> > > sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> > > 
> > > I looked at it deeper and found out that in PCI subsystem code is race
> > > condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> > > of these functions calls pci_create_sysfs_dev_files() and calling this
> > > function more times for same pci device throws above error message.
> > > 
> > > There can be two different race conditions:
> > > 
> > > 1. pci_bus_add_device() called pcibios_bus_add_device() or
> > > pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> > > Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> > > was called for newly registered device. In this case function
> > > pci_create_sysfs_dev_files() is called two times, ones from
> > > pci_bus_add_device() and once from pci_sysfs_init().
> > > 
> > > 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> > > which unblock calling pci_create_sysfs_dev_files(). Then another bus
> > > registers new PCI device and calls pci_bus_add_device() which calls
> > > pci_create_sysfs_dev_files() and registers sysfs files. Function
> > > pci_sysfs_init() continues execution and calls function
> > > pci_create_sysfs_dev_files() also for this newly registered device. So
> > > pci_create_sysfs_dev_files() is again called two times.
> > > 
> > > 
> > > I workaround both race conditions I created following hack patch. After
> > > applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> > > error message anymore.
> > > 
> > > Can you look at it how to fix both race conditions in proper way?
> > 
> > Is this workaround diff enough? Or are you going to prepare something better?
> > 
> > Please let me know if I should send this diff as regular patch.
> > 
> > > 
> > > diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
> > > index 8e40b3e6da77..691be2258c4e 100644
> > > --- a/drivers/pci/bus.c
> > > +++ b/drivers/pci/bus.c
> > > @@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
> > >  	 */
> > >  	pcibios_bus_add_device(dev);
> > >  	pci_fixup_device(pci_fixup_final, dev);
> > > -	pci_create_sysfs_dev_files(dev);
> > > +	pci_create_sysfs_dev_files(dev, false);
> > >  	pci_proc_attach_device(dev);
> > >  	pci_bridge_d3_update(dev);
> > >  
> > > diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
> > > index 6d78df981d41..b0c4852a51dd 100644
> > > --- a/drivers/pci/pci-sysfs.c
> > > +++ b/drivers/pci/pci-sysfs.c
> > > @@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
> > >  	return retval;
> > >  }
> > >  
> > > -int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
> > > +int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
> > >  {
> > >  	int retval;
> > >  	int rom_size;
> > >  	struct bin_attribute *attr;
> > >  
> > > -	if (!sysfs_initialized)
> > > +	if (!sysfs_initializing && !sysfs_initialized)
> > >  		return -EACCES;
> > >  
> > >  	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
> > > @@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
> > >  static int __init pci_sysfs_init(void)
> > >  {
> > >  	struct pci_dev *pdev = NULL;
> > > -	int retval;
> > > +	int retval = 0;
> > >  
> > > -	sysfs_initialized = 1;
> > >  	for_each_pci_dev(pdev) {
> > > -		retval = pci_create_sysfs_dev_files(pdev);
> > > +		if (!pci_dev_is_added(pdev))
> > > +			continue;
> > > +		retval = pci_create_sysfs_dev_files(pdev, true);
> > >  		if (retval) {
> > >  			pci_dev_put(pdev);
> > > -			return retval;
> > > +			goto out;
> > >  		}
> > >  	}
> > >  
> > > -	return 0;
> > > +out:
> > > +	sysfs_initialized = 1;
> > > +	return retval;
> > >  }
> > >  late_initcall(pci_sysfs_init);
> > >  
> > > diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
> > > index 6d3f75867106..304294c7171e 100644
> > > --- a/drivers/pci/pci.h
> > > +++ b/drivers/pci/pci.h
> > > @@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
> > >  
> > >  /* Functions internal to the PCI core code */
> > >  
> > > -int pci_create_sysfs_dev_files(struct pci_dev *pdev);
> > > +int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
> > >  void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
> > >  #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
> > >  static inline void pci_create_firmware_label_files(struct pci_dev *pdev)
> > > 

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Bjorn Helgaas]

On Mon, Oct 05, 2020 at 10:20:18AM +0200, Pali Rohár wrote:
> PING?

Sorry, I guess nobody has had the right combination of time, interest,
and knowledge to work on this.  I'll try to take a look this week.

> On Wednesday 09 September 2020 13:28:50 Pali Rohár wrote:
> > Hello! I'm adding more people to loop.
> > 
> > Can somebody look at these race conditions and my patch?
> > 
> > On Friday 14 August 2020 10:08:24 Pali Rohár wrote:
> > > Hello! I would like to remind this issue which I reported month ago.
> > > 
> > > On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> > > > Hello Bjorn!
> > > > 
> > > > I see following error message in dmesg which looks like a race condition:
> > > > 
> > > > sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> > > > 
> > > > I looked at it deeper and found out that in PCI subsystem code is race
> > > > condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> > > > of these functions calls pci_create_sysfs_dev_files() and calling this
> > > > function more times for same pci device throws above error message.
> > > > 
> > > > There can be two different race conditions:
> > > > 
> > > > 1. pci_bus_add_device() called pcibios_bus_add_device() or
> > > > pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> > > > Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> > > > was called for newly registered device. In this case function
> > > > pci_create_sysfs_dev_files() is called two times, ones from
> > > > pci_bus_add_device() and once from pci_sysfs_init().
> > > > 
> > > > 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> > > > which unblock calling pci_create_sysfs_dev_files(). Then another bus
> > > > registers new PCI device and calls pci_bus_add_device() which calls
> > > > pci_create_sysfs_dev_files() and registers sysfs files. Function
> > > > pci_sysfs_init() continues execution and calls function
> > > > pci_create_sysfs_dev_files() also for this newly registered device. So
> > > > pci_create_sysfs_dev_files() is again called two times.
> > > > 
> > > > 
> > > > I workaround both race conditions I created following hack patch. After
> > > > applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> > > > error message anymore.
> > > > 
> > > > Can you look at it how to fix both race conditions in proper way?
> > > 
> > > Is this workaround diff enough? Or are you going to prepare something better?
> > > 
> > > Please let me know if I should send this diff as regular patch.
> > > 
> > > > 
> > > > diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
> > > > index 8e40b3e6da77..691be2258c4e 100644
> > > > --- a/drivers/pci/bus.c
> > > > +++ b/drivers/pci/bus.c
> > > > @@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
> > > >  	 */
> > > >  	pcibios_bus_add_device(dev);
> > > >  	pci_fixup_device(pci_fixup_final, dev);
> > > > -	pci_create_sysfs_dev_files(dev);
> > > > +	pci_create_sysfs_dev_files(dev, false);
> > > >  	pci_proc_attach_device(dev);
> > > >  	pci_bridge_d3_update(dev);
> > > >  
> > > > diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
> > > > index 6d78df981d41..b0c4852a51dd 100644
> > > > --- a/drivers/pci/pci-sysfs.c
> > > > +++ b/drivers/pci/pci-sysfs.c
> > > > @@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
> > > >  	return retval;
> > > >  }
> > > >  
> > > > -int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
> > > > +int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
> > > >  {
> > > >  	int retval;
> > > >  	int rom_size;
> > > >  	struct bin_attribute *attr;
> > > >  
> > > > -	if (!sysfs_initialized)
> > > > +	if (!sysfs_initializing && !sysfs_initialized)
> > > >  		return -EACCES;
> > > >  
> > > >  	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
> > > > @@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
> > > >  static int __init pci_sysfs_init(void)
> > > >  {
> > > >  	struct pci_dev *pdev = NULL;
> > > > -	int retval;
> > > > +	int retval = 0;
> > > >  
> > > > -	sysfs_initialized = 1;
> > > >  	for_each_pci_dev(pdev) {
> > > > -		retval = pci_create_sysfs_dev_files(pdev);
> > > > +		if (!pci_dev_is_added(pdev))
> > > > +			continue;
> > > > +		retval = pci_create_sysfs_dev_files(pdev, true);
> > > >  		if (retval) {
> > > >  			pci_dev_put(pdev);
> > > > -			return retval;
> > > > +			goto out;
> > > >  		}
> > > >  	}
> > > >  
> > > > -	return 0;
> > > > +out:
> > > > +	sysfs_initialized = 1;
> > > > +	return retval;
> > > >  }
> > > >  late_initcall(pci_sysfs_init);
> > > >  
> > > > diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
> > > > index 6d3f75867106..304294c7171e 100644
> > > > --- a/drivers/pci/pci.h
> > > > +++ b/drivers/pci/pci.h
> > > > @@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
> > > >  
> > > >  /* Functions internal to the PCI core code */
> > > >  
> > > > -int pci_create_sysfs_dev_files(struct pci_dev *pdev);
> > > > +int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
> > > >  void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
> > > >  #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
> > > >  static inline void pci_create_firmware_label_files(struct pci_dev *pdev)
> > > > 

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Bjorn Helgaas]

[+cc Krzysztof, Yinghai]

On Wed, Sep 09, 2020 at 01:28:50PM +0200, Pali Rohár wrote:
> Hello! I'm adding more people to loop.
> 
> Can somebody look at these race conditions and my patch?
> 
> On Friday 14 August 2020 10:08:24 Pali Rohár wrote:
> > Hello! I would like to remind this issue which I reported month ago.
> > 
> > On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> > > Hello Bjorn!
> > > 
> > > I see following error message in dmesg which looks like a race condition:
> > > 
> > > sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> > > 
> > > I looked at it deeper and found out that in PCI subsystem code is race
> > > condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> > > of these functions calls pci_create_sysfs_dev_files() and calling this
> > > function more times for same pci device throws above error message.
> > > 
> > > There can be two different race conditions:
> > > 
> > > 1. pci_bus_add_device() called pcibios_bus_add_device() or
> > > pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> > > Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> > > was called for newly registered device. In this case function
> > > pci_create_sysfs_dev_files() is called two times, ones from
> > > pci_bus_add_device() and once from pci_sysfs_init().
> > > 
> > > 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> > > which unblock calling pci_create_sysfs_dev_files(). Then another bus
> > > registers new PCI device and calls pci_bus_add_device() which calls
> > > pci_create_sysfs_dev_files() and registers sysfs files. Function
> > > pci_sysfs_init() continues execution and calls function
> > > pci_create_sysfs_dev_files() also for this newly registered device. So
> > > pci_create_sysfs_dev_files() is again called two times.
> > > 
> > > 
> > > I workaround both race conditions I created following hack patch. After
> > > applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> > > error message anymore.
> > > 
> > > Can you look at it how to fix both race conditions in proper way?
> > 
> > Is this workaround diff enough? Or are you going to prepare
> > something better?
> > 
> > Please let me know if I should send this diff as regular patch.

I'm not really a fan of this because pci_sysfs_init() is a bit of a
hack to begin with, and this makes it even more complicated.

It's not obvious from the code why we need pci_sysfs_init(), but
Yinghai hinted [1] that we need to create sysfs after assigning
resources.  I experimented by removing pci_sysfs_init() and skipping
the ROM BAR sizing.  In that case, we create sysfs files in
pci_bus_add_device() and later assign space for the ROM BAR, so we
fail to create the "rom" sysfs file.

The current solution to that is to delay the sysfs files until
pci_sysfs_init(), a late_initcall(), which runs after resource
assignments.  But I think it would be better if we could create the
sysfs file when we assign the BAR.  Then we could get rid of the
late_initcall() and that implicit ordering requirement.

But I haven't tried to code it up, so it's probably more complicated
than this.  I guess ideally we would assign all the resources before
pci_bus_add_device().  If we could do that, we could just remove
pci_sysfs_init() and everything would just work, but I think that's a
HUGE can of worms.

[1] https://lore.kernel.org/linux-pci/CAE9FiQWBXHgz-gWCmpWLaBOfQQJwtRZemV6Ut9GVw_KJ-dTGTA@mail.gmail.com/

> > > diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
> > > index 8e40b3e6da77..691be2258c4e 100644
> > > --- a/drivers/pci/bus.c
> > > +++ b/drivers/pci/bus.c
> > > @@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
> > >  	 */
> > >  	pcibios_bus_add_device(dev);
> > >  	pci_fixup_device(pci_fixup_final, dev);
> > > -	pci_create_sysfs_dev_files(dev);
> > > +	pci_create_sysfs_dev_files(dev, false);
> > >  	pci_proc_attach_device(dev);
> > >  	pci_bridge_d3_update(dev);
> > >  
> > > diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
> > > index 6d78df981d41..b0c4852a51dd 100644
> > > --- a/drivers/pci/pci-sysfs.c
> > > +++ b/drivers/pci/pci-sysfs.c
> > > @@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
> > >  	return retval;
> > >  }
> > >  
> > > -int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
> > > +int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
> > >  {
> > >  	int retval;
> > >  	int rom_size;
> > >  	struct bin_attribute *attr;
> > >  
> > > -	if (!sysfs_initialized)
> > > +	if (!sysfs_initializing && !sysfs_initialized)
> > >  		return -EACCES;
> > >  
> > >  	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
> > > @@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
> > >  static int __init pci_sysfs_init(void)
> > >  {
> > >  	struct pci_dev *pdev = NULL;
> > > -	int retval;
> > > +	int retval = 0;
> > >  
> > > -	sysfs_initialized = 1;
> > >  	for_each_pci_dev(pdev) {
> > > -		retval = pci_create_sysfs_dev_files(pdev);
> > > +		if (!pci_dev_is_added(pdev))
> > > +			continue;
> > > +		retval = pci_create_sysfs_dev_files(pdev, true);
> > >  		if (retval) {
> > >  			pci_dev_put(pdev);
> > > -			return retval;
> > > +			goto out;
> > >  		}
> > >  	}
> > >  
> > > -	return 0;
> > > +out:
> > > +	sysfs_initialized = 1;
> > > +	return retval;
> > >  }
> > >  late_initcall(pci_sysfs_init);
> > >  
> > > diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
> > > index 6d3f75867106..304294c7171e 100644
> > > --- a/drivers/pci/pci.h
> > > +++ b/drivers/pci/pci.h
> > > @@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
> > >  
> > >  /* Functions internal to the PCI core code */
> > >  
> > > -int pci_create_sysfs_dev_files(struct pci_dev *pdev);
> > > +int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
> > >  void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
> > >  #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
> > >  static inline void pci_create_firmware_label_files(struct pci_dev *pdev)
> > > 

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Oliver O'Halloran]

On Wed, Oct 7, 2020 at 10:26 AM Bjorn Helgaas <helgaas@kernel.org> wrote:
>
> I'm not really a fan of this because pci_sysfs_init() is a bit of a
> hack to begin with, and this makes it even more complicated.
>
> It's not obvious from the code why we need pci_sysfs_init(), but
> Yinghai hinted [1] that we need to create sysfs after assigning
> resources.  I experimented by removing pci_sysfs_init() and skipping
> the ROM BAR sizing.  In that case, we create sysfs files in
> pci_bus_add_device() and later assign space for the ROM BAR, so we
> fail to create the "rom" sysfs file.
>
> The current solution to that is to delay the sysfs files until
> pci_sysfs_init(), a late_initcall(), which runs after resource
> assignments.  But I think it would be better if we could create the
> sysfs file when we assign the BAR.  Then we could get rid of the
> late_initcall() and that implicit ordering requirement.

You could probably fix that by using an attribute_group to control
whether the attribute shows up in sysfs or not. The .is_visible() for
the group can look at the current state of the device and hide the rom
attribute if the BAR isn't assigned or doesn't exist. That way we
don't need to care when the actual assignment occurs.

> But I haven't tried to code it up, so it's probably more complicated
> than this.  I guess ideally we would assign all the resources before
> pci_bus_add_device().  If we could do that, we could just remove
> pci_sysfs_init() and everything would just work, but I think that's a
> HUGE can of worms.

I was under the impression the whole point of pci_bus_add_device() was
to handle any initialisation that needed to be done after resources
were assigned. Is the ROM BAR being potentially unassigned an x86ism
or is there some bigger point I'm missing?

Oliver

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Tuesday 06 October 2020 17:22:22 Bjorn Helgaas wrote:
> [+cc Krzysztof, Yinghai]
> 
> On Wed, Sep 09, 2020 at 01:28:50PM +0200, Pali Rohár wrote:
> > Hello! I'm adding more people to loop.
> > 
> > Can somebody look at these race conditions and my patch?
> > 
> > On Friday 14 August 2020 10:08:24 Pali Rohár wrote:
> > > Hello! I would like to remind this issue which I reported month ago.
> > > 
> > > On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> > > > Hello Bjorn!
> > > > 
> > > > I see following error message in dmesg which looks like a race condition:
> > > > 
> > > > sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> > > > 
> > > > I looked at it deeper and found out that in PCI subsystem code is race
> > > > condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> > > > of these functions calls pci_create_sysfs_dev_files() and calling this
> > > > function more times for same pci device throws above error message.
> > > > 
> > > > There can be two different race conditions:
> > > > 
> > > > 1. pci_bus_add_device() called pcibios_bus_add_device() or
> > > > pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> > > > Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> > > > was called for newly registered device. In this case function
> > > > pci_create_sysfs_dev_files() is called two times, ones from
> > > > pci_bus_add_device() and once from pci_sysfs_init().
> > > > 
> > > > 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> > > > which unblock calling pci_create_sysfs_dev_files(). Then another bus
> > > > registers new PCI device and calls pci_bus_add_device() which calls
> > > > pci_create_sysfs_dev_files() and registers sysfs files. Function
> > > > pci_sysfs_init() continues execution and calls function
> > > > pci_create_sysfs_dev_files() also for this newly registered device. So
> > > > pci_create_sysfs_dev_files() is again called two times.
> > > > 
> > > > 
> > > > I workaround both race conditions I created following hack patch. After
> > > > applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> > > > error message anymore.
> > > > 
> > > > Can you look at it how to fix both race conditions in proper way?
> > > 
> > > Is this workaround diff enough? Or are you going to prepare
> > > something better?
> > > 
> > > Please let me know if I should send this diff as regular patch.
> 
> I'm not really a fan of this because pci_sysfs_init() is a bit of a
> hack to begin with, and this makes it even more complicated.

I understand, but the two race conditions are in this pci_sysfs_init()
function. So either it needs to be fixed or code changed, so this
function can be removed.

I'm hitting these race conditions randomly on pci aardvark controller
driver- I prepared patch which speed up initialization of this driver,
but also increase probability that it hits above race conditions :-(

> It's not obvious from the code why we need pci_sysfs_init(), but
> Yinghai hinted [1] that we need to create sysfs after assigning
> resources.  I experimented by removing pci_sysfs_init() and skipping
> the ROM BAR sizing.  In that case, we create sysfs files in
> pci_bus_add_device() and later assign space for the ROM BAR, so we
> fail to create the "rom" sysfs file.

Thank you for explanation. I think it should be documented somewhere in
the code as it is really not obvious.

> The current solution to that is to delay the sysfs files until
> pci_sysfs_init(), a late_initcall(), which runs after resource
> assignments.  But I think it would be better if we could create the
> sysfs file when we assign the BAR.  Then we could get rid of the
> late_initcall() and that implicit ordering requirement.
> 
> But I haven't tried to code it up, so it's probably more complicated
> than this.  I guess ideally we would assign all the resources before
> pci_bus_add_device().  If we could do that, we could just remove
> pci_sysfs_init() and everything would just work, but I think that's a
> HUGE can of worms.
> 
> [1] https://lore.kernel.org/linux-pci/CAE9FiQWBXHgz-gWCmpWLaBOfQQJwtRZemV6Ut9GVw_KJ-dTGTA@mail.gmail.com/
> 
> > > > diff --git a/drivers/pci/bus.c b/drivers/pci/bus.c
> > > > index 8e40b3e6da77..691be2258c4e 100644
> > > > --- a/drivers/pci/bus.c
> > > > +++ b/drivers/pci/bus.c
> > > > @@ -316,7 +316,7 @@ void pci_bus_add_device(struct pci_dev *dev)
> > > >  	 */
> > > >  	pcibios_bus_add_device(dev);
> > > >  	pci_fixup_device(pci_fixup_final, dev);
> > > > -	pci_create_sysfs_dev_files(dev);
> > > > +	pci_create_sysfs_dev_files(dev, false);
> > > >  	pci_proc_attach_device(dev);
> > > >  	pci_bridge_d3_update(dev);
> > > >  
> > > > diff --git a/drivers/pci/pci-sysfs.c b/drivers/pci/pci-sysfs.c
> > > > index 6d78df981d41..b0c4852a51dd 100644
> > > > --- a/drivers/pci/pci-sysfs.c
> > > > +++ b/drivers/pci/pci-sysfs.c
> > > > @@ -1328,13 +1328,13 @@ static int pci_create_capabilities_sysfs(struct pci_dev *dev)
> > > >  	return retval;
> > > >  }
> > > >  
> > > > -int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev)
> > > > +int __must_check pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing)
> > > >  {
> > > >  	int retval;
> > > >  	int rom_size;
> > > >  	struct bin_attribute *attr;
> > > >  
> > > > -	if (!sysfs_initialized)
> > > > +	if (!sysfs_initializing && !sysfs_initialized)
> > > >  		return -EACCES;
> > > >  
> > > >  	if (pdev->cfg_size > PCI_CFG_SPACE_SIZE)
> > > > @@ -1437,18 +1437,21 @@ void pci_remove_sysfs_dev_files(struct pci_dev *pdev)
> > > >  static int __init pci_sysfs_init(void)
> > > >  {
> > > >  	struct pci_dev *pdev = NULL;
> > > > -	int retval;
> > > > +	int retval = 0;
> > > >  
> > > > -	sysfs_initialized = 1;
> > > >  	for_each_pci_dev(pdev) {
> > > > -		retval = pci_create_sysfs_dev_files(pdev);
> > > > +		if (!pci_dev_is_added(pdev))
> > > > +			continue;
> > > > +		retval = pci_create_sysfs_dev_files(pdev, true);
> > > >  		if (retval) {
> > > >  			pci_dev_put(pdev);
> > > > -			return retval;
> > > > +			goto out;
> > > >  		}
> > > >  	}
> > > >  
> > > > -	return 0;
> > > > +out:
> > > > +	sysfs_initialized = 1;
> > > > +	return retval;
> > > >  }
> > > >  late_initcall(pci_sysfs_init);
> > > >  
> > > > diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h
> > > > index 6d3f75867106..304294c7171e 100644
> > > > --- a/drivers/pci/pci.h
> > > > +++ b/drivers/pci/pci.h
> > > > @@ -19,7 +19,7 @@ bool pcie_cap_has_rtctl(const struct pci_dev *dev);
> > > >  
> > > >  /* Functions internal to the PCI core code */
> > > >  
> > > > -int pci_create_sysfs_dev_files(struct pci_dev *pdev);
> > > > +int pci_create_sysfs_dev_files(struct pci_dev *pdev, bool sysfs_initializing);
> > > >  void pci_remove_sysfs_dev_files(struct pci_dev *pdev);
> > > >  #if !defined(CONFIG_DMI) && !defined(CONFIG_ACPI)
> > > >  static inline void pci_create_firmware_label_files(struct pci_dev *pdev)
> > > > 

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Wednesday 07 October 2020 12:47:40 Oliver O'Halloran wrote:
> On Wed, Oct 7, 2020 at 10:26 AM Bjorn Helgaas <helgaas@kernel.org> wrote:
> >
> > I'm not really a fan of this because pci_sysfs_init() is a bit of a
> > hack to begin with, and this makes it even more complicated.
> >
> > It's not obvious from the code why we need pci_sysfs_init(), but
> > Yinghai hinted [1] that we need to create sysfs after assigning
> > resources.  I experimented by removing pci_sysfs_init() and skipping
> > the ROM BAR sizing.  In that case, we create sysfs files in
> > pci_bus_add_device() and later assign space for the ROM BAR, so we
> > fail to create the "rom" sysfs file.
> >
> > The current solution to that is to delay the sysfs files until
> > pci_sysfs_init(), a late_initcall(), which runs after resource
> > assignments.  But I think it would be better if we could create the
> > sysfs file when we assign the BAR.  Then we could get rid of the
> > late_initcall() and that implicit ordering requirement.
> 
> You could probably fix that by using an attribute_group to control
> whether the attribute shows up in sysfs or not. The .is_visible() for
> the group can look at the current state of the device and hide the rom
> attribute if the BAR isn't assigned or doesn't exist. That way we
> don't need to care when the actual assignment occurs.

And cannot we just return e.g. -ENODATA (or other error code) for those
problematic sysfs nodes until late_initcall() is called?

> > But I haven't tried to code it up, so it's probably more complicated
> > than this.  I guess ideally we would assign all the resources before
> > pci_bus_add_device().  If we could do that, we could just remove
> > pci_sysfs_init() and everything would just work, but I think that's a
> > HUGE can of worms.
> 
> I was under the impression the whole point of pci_bus_add_device() was
> to handle any initialisation that needed to be done after resources
> were assigned. Is the ROM BAR being potentially unassigned an x86ism
> or is there some bigger point I'm missing?
> 
> Oliver

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Bjorn Helgaas]

On Wed, Oct 07, 2020 at 10:14:00AM +0200, Pali Rohár wrote:
> On Wednesday 07 October 2020 12:47:40 Oliver O'Halloran wrote:
> > On Wed, Oct 7, 2020 at 10:26 AM Bjorn Helgaas <helgaas@kernel.org> wrote:
> > >
> > > I'm not really a fan of this because pci_sysfs_init() is a bit of a
> > > hack to begin with, and this makes it even more complicated.
> > >
> > > It's not obvious from the code why we need pci_sysfs_init(), but
> > > Yinghai hinted [1] that we need to create sysfs after assigning
> > > resources.  I experimented by removing pci_sysfs_init() and skipping
> > > the ROM BAR sizing.  In that case, we create sysfs files in
> > > pci_bus_add_device() and later assign space for the ROM BAR, so we
> > > fail to create the "rom" sysfs file.
> > >
> > > The current solution to that is to delay the sysfs files until
> > > pci_sysfs_init(), a late_initcall(), which runs after resource
> > > assignments.  But I think it would be better if we could create the
> > > sysfs file when we assign the BAR.  Then we could get rid of the
> > > late_initcall() and that implicit ordering requirement.
> > 
> > You could probably fix that by using an attribute_group to control
> > whether the attribute shows up in sysfs or not. The .is_visible() for
> > the group can look at the current state of the device and hide the rom
> > attribute if the BAR isn't assigned or doesn't exist. That way we
> > don't need to care when the actual assignment occurs.
> 
> And cannot we just return e.g. -ENODATA (or other error code) for those
> problematic sysfs nodes until late_initcall() is called?

I really like Oliver's idea and I think we should push on that to see
if it can be made to work.  If so, we can remove the late_initcall()
completely.

> > > But I haven't tried to code it up, so it's probably more complicated
> > > than this.  I guess ideally we would assign all the resources before
> > > pci_bus_add_device().  If we could do that, we could just remove
> > > pci_sysfs_init() and everything would just work, but I think that's a
> > > HUGE can of worms.
> > 
> > I was under the impression the whole point of pci_bus_add_device() was
> > to handle any initialisation that needed to be done after resources
> > were assigned. Is the ROM BAR being potentially unassigned an x86ism
> > or is there some bigger point I'm missing?

We can't assign resources for each device as we enumerate it because
we don't know what's in use by other devices yet to be enumerated.
That part is generic, not x86-specific.

The part that is x86-specific (or at least specific to systems using
ACPI) is that the ACPI core doesn't reserve resources used by ACPI
devices.  Sometimes those resources are included in the PCI host
bridge windows, and we don't want to assign them to PCI devices.

I didn't trace this all the way, but the pcibios_assign_resources()
and pnp_system_init() comments look relevant.  It's a little concerning
that they're both fs_initcalls() and the ordering looks important, but
it would only be by accident of link ordering that pnp_system_init()
happens first.

Bjorn

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Bjorn Helgaas]

On Wed, Oct 07, 2020 at 11:14:34AM -0500, Bjorn Helgaas wrote:
> On Wed, Oct 07, 2020 at 10:14:00AM +0200, Pali Rohár wrote:
> > On Wednesday 07 October 2020 12:47:40 Oliver O'Halloran wrote:
> > > On Wed, Oct 7, 2020 at 10:26 AM Bjorn Helgaas <helgaas@kernel.org> wrote:
> > > >
> > > > I'm not really a fan of this because pci_sysfs_init() is a bit of a
> > > > hack to begin with, and this makes it even more complicated.
> > > >
> > > > It's not obvious from the code why we need pci_sysfs_init(), but
> > > > Yinghai hinted [1] that we need to create sysfs after assigning
> > > > resources.  I experimented by removing pci_sysfs_init() and skipping
> > > > the ROM BAR sizing.  In that case, we create sysfs files in
> > > > pci_bus_add_device() and later assign space for the ROM BAR, so we
> > > > fail to create the "rom" sysfs file.
> > > >
> > > > The current solution to that is to delay the sysfs files until
> > > > pci_sysfs_init(), a late_initcall(), which runs after resource
> > > > assignments.  But I think it would be better if we could create the
> > > > sysfs file when we assign the BAR.  Then we could get rid of the
> > > > late_initcall() and that implicit ordering requirement.
> > > 
> > > You could probably fix that by using an attribute_group to control
> > > whether the attribute shows up in sysfs or not. The .is_visible() for
> > > the group can look at the current state of the device and hide the rom
> > > attribute if the BAR isn't assigned or doesn't exist. That way we
> > > don't need to care when the actual assignment occurs.
> > 
> > And cannot we just return e.g. -ENODATA (or other error code) for those
> > problematic sysfs nodes until late_initcall() is called?
> 
> I really like Oliver's idea and I think we should push on that to see
> if it can be made to work.  If so, we can remove the late_initcall()
> completely.
> 
> > > > But I haven't tried to code it up, so it's probably more complicated
> > > > than this.  I guess ideally we would assign all the resources before
> > > > pci_bus_add_device().  If we could do that, we could just remove
> > > > pci_sysfs_init() and everything would just work, but I think that's a
> > > > HUGE can of worms.
> > > 
> > > I was under the impression the whole point of pci_bus_add_device() was
> > > to handle any initialisation that needed to be done after resources
> > > were assigned. Is the ROM BAR being potentially unassigned an x86ism
> > > or is there some bigger point I'm missing?
> 
> We can't assign resources for each device as we enumerate it because
> we don't know what's in use by other devices yet to be enumerated.
> That part is generic, not x86-specific.
> 
> The part that is x86-specific (or at least specific to systems using
> ACPI) is that the ACPI core doesn't reserve resources used by ACPI
> devices.  Sometimes those resources are included in the PCI host
> bridge windows, and we don't want to assign them to PCI devices.
> 
> I didn't trace this all the way, but the pcibios_assign_resources()
> and pnp_system_init() comments look relevant.  It's a little concerning
> that they're both fs_initcalls() and the ordering looks important, but
> it would only be by accident of link ordering that pnp_system_init()
> happens first.

Pali, what's your thought on this?  Do you plan to work on this
yourself?  If not and if you can live with your workaround a while
longer, I think Krzysztof might be interested in taking a crack at it.
I would just hate to see you guys duplicate each others' work :)

Bjorn

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Thursday 08 October 2020 14:59:07 Bjorn Helgaas wrote:
> On Wed, Oct 07, 2020 at 11:14:34AM -0500, Bjorn Helgaas wrote:
> > On Wed, Oct 07, 2020 at 10:14:00AM +0200, Pali Rohár wrote:
> > > On Wednesday 07 October 2020 12:47:40 Oliver O'Halloran wrote:
> > > > On Wed, Oct 7, 2020 at 10:26 AM Bjorn Helgaas <helgaas@kernel.org> wrote:
> > > > >
> > > > > I'm not really a fan of this because pci_sysfs_init() is a bit of a
> > > > > hack to begin with, and this makes it even more complicated.
> > > > >
> > > > > It's not obvious from the code why we need pci_sysfs_init(), but
> > > > > Yinghai hinted [1] that we need to create sysfs after assigning
> > > > > resources.  I experimented by removing pci_sysfs_init() and skipping
> > > > > the ROM BAR sizing.  In that case, we create sysfs files in
> > > > > pci_bus_add_device() and later assign space for the ROM BAR, so we
> > > > > fail to create the "rom" sysfs file.
> > > > >
> > > > > The current solution to that is to delay the sysfs files until
> > > > > pci_sysfs_init(), a late_initcall(), which runs after resource
> > > > > assignments.  But I think it would be better if we could create the
> > > > > sysfs file when we assign the BAR.  Then we could get rid of the
> > > > > late_initcall() and that implicit ordering requirement.
> > > > 
> > > > You could probably fix that by using an attribute_group to control
> > > > whether the attribute shows up in sysfs or not. The .is_visible() for
> > > > the group can look at the current state of the device and hide the rom
> > > > attribute if the BAR isn't assigned or doesn't exist. That way we
> > > > don't need to care when the actual assignment occurs.
> > > 
> > > And cannot we just return e.g. -ENODATA (or other error code) for those
> > > problematic sysfs nodes until late_initcall() is called?
> > 
> > I really like Oliver's idea and I think we should push on that to see
> > if it can be made to work.  If so, we can remove the late_initcall()
> > completely.
> > 
> > > > > But I haven't tried to code it up, so it's probably more complicated
> > > > > than this.  I guess ideally we would assign all the resources before
> > > > > pci_bus_add_device().  If we could do that, we could just remove
> > > > > pci_sysfs_init() and everything would just work, but I think that's a
> > > > > HUGE can of worms.
> > > > 
> > > > I was under the impression the whole point of pci_bus_add_device() was
> > > > to handle any initialisation that needed to be done after resources
> > > > were assigned. Is the ROM BAR being potentially unassigned an x86ism
> > > > or is there some bigger point I'm missing?
> > 
> > We can't assign resources for each device as we enumerate it because
> > we don't know what's in use by other devices yet to be enumerated.
> > That part is generic, not x86-specific.
> > 
> > The part that is x86-specific (or at least specific to systems using
> > ACPI) is that the ACPI core doesn't reserve resources used by ACPI
> > devices.  Sometimes those resources are included in the PCI host
> > bridge windows, and we don't want to assign them to PCI devices.
> > 
> > I didn't trace this all the way, but the pcibios_assign_resources()
> > and pnp_system_init() comments look relevant.  It's a little concerning
> > that they're both fs_initcalls() and the ordering looks important, but
> > it would only be by accident of link ordering that pnp_system_init()
> > happens first.
> 
> Pali, what's your thought on this?  Do you plan to work on this
> yourself?  If not and if you can live with your workaround a while
> longer, I think Krzysztof might be interested in taking a crack at it.
> I would just hate to see you guys duplicate each others' work :)

Hello Bjorn!

If Krzysztof wants and would be working on this issue I can let it as is
for now.

But we should think how to deliver fix for this issue also into stable
kernels where this race condition is happening.

I think that my workaround avoid those two race conditions and if proper
fix (= removal of pci_sysfs_init function) would take a long, what about
trying to workaround that race condition for now?

My "fix" is relatively small and simple, so it should not be much hard
to review it.

Krzysztof, what do you think?

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

Hello Krzysztof!

On Friday 09 October 2020 10:08:53 Pali Rohár wrote:
> On Thursday 08 October 2020 14:59:07 Bjorn Helgaas wrote:
> > On Wed, Oct 07, 2020 at 11:14:34AM -0500, Bjorn Helgaas wrote:
> > > On Wed, Oct 07, 2020 at 10:14:00AM +0200, Pali Rohár wrote:
> > > > On Wednesday 07 October 2020 12:47:40 Oliver O'Halloran wrote:
> > > > > On Wed, Oct 7, 2020 at 10:26 AM Bjorn Helgaas <helgaas@kernel.org> wrote:
> > > > > >
> > > > > > I'm not really a fan of this because pci_sysfs_init() is a bit of a
> > > > > > hack to begin with, and this makes it even more complicated.
> > > > > >
> > > > > > It's not obvious from the code why we need pci_sysfs_init(), but
> > > > > > Yinghai hinted [1] that we need to create sysfs after assigning
> > > > > > resources.  I experimented by removing pci_sysfs_init() and skipping
> > > > > > the ROM BAR sizing.  In that case, we create sysfs files in
> > > > > > pci_bus_add_device() and later assign space for the ROM BAR, so we
> > > > > > fail to create the "rom" sysfs file.
> > > > > >
> > > > > > The current solution to that is to delay the sysfs files until
> > > > > > pci_sysfs_init(), a late_initcall(), which runs after resource
> > > > > > assignments.  But I think it would be better if we could create the
> > > > > > sysfs file when we assign the BAR.  Then we could get rid of the
> > > > > > late_initcall() and that implicit ordering requirement.
> > > > > 
> > > > > You could probably fix that by using an attribute_group to control
> > > > > whether the attribute shows up in sysfs or not. The .is_visible() for
> > > > > the group can look at the current state of the device and hide the rom
> > > > > attribute if the BAR isn't assigned or doesn't exist. That way we
> > > > > don't need to care when the actual assignment occurs.
> > > > 
> > > > And cannot we just return e.g. -ENODATA (or other error code) for those
> > > > problematic sysfs nodes until late_initcall() is called?
> > > 
> > > I really like Oliver's idea and I think we should push on that to see
> > > if it can be made to work.  If so, we can remove the late_initcall()
> > > completely.
> > > 
> > > > > > But I haven't tried to code it up, so it's probably more complicated
> > > > > > than this.  I guess ideally we would assign all the resources before
> > > > > > pci_bus_add_device().  If we could do that, we could just remove
> > > > > > pci_sysfs_init() and everything would just work, but I think that's a
> > > > > > HUGE can of worms.
> > > > > 
> > > > > I was under the impression the whole point of pci_bus_add_device() was
> > > > > to handle any initialisation that needed to be done after resources
> > > > > were assigned. Is the ROM BAR being potentially unassigned an x86ism
> > > > > or is there some bigger point I'm missing?
> > > 
> > > We can't assign resources for each device as we enumerate it because
> > > we don't know what's in use by other devices yet to be enumerated.
> > > That part is generic, not x86-specific.
> > > 
> > > The part that is x86-specific (or at least specific to systems using
> > > ACPI) is that the ACPI core doesn't reserve resources used by ACPI
> > > devices.  Sometimes those resources are included in the PCI host
> > > bridge windows, and we don't want to assign them to PCI devices.
> > > 
> > > I didn't trace this all the way, but the pcibios_assign_resources()
> > > and pnp_system_init() comments look relevant.  It's a little concerning
> > > that they're both fs_initcalls() and the ordering looks important, but
> > > it would only be by accident of link ordering that pnp_system_init()
> > > happens first.
> > 
> > Pali, what's your thought on this?  Do you plan to work on this
> > yourself?  If not and if you can live with your workaround a while
> > longer, I think Krzysztof might be interested in taking a crack at it.
> > I would just hate to see you guys duplicate each others' work :)
> 
> Hello Bjorn!
> 
> If Krzysztof wants and would be working on this issue I can let it as is
> for now.

Krzysztof, as Bjorn wrote, do you want to take this issue?

> But we should think how to deliver fix for this issue also into stable
> kernels where this race condition is happening.
> 
> I think that my workaround avoid those two race conditions and if proper
> fix (= removal of pci_sysfs_init function) would take a long, what about
> trying to workaround that race condition for now?
> 
> My "fix" is relatively small and simple, so it should not be much hard
> to review it.
> 
> Krzysztof, what do you think?

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Tuesday 06 October 2020 17:22:22 Bjorn Helgaas wrote:
> It's not obvious from the code why we need pci_sysfs_init(), but
> Yinghai hinted [1] that we need to create sysfs after assigning
> resources.  I experimented by removing pci_sysfs_init() and skipping
> the ROM BAR sizing.  In that case, we create sysfs files in
> pci_bus_add_device() and later assign space for the ROM BAR, so we
> fail to create the "rom" sysfs file.
> 
> The current solution to that is to delay the sysfs files until
> pci_sysfs_init(), a late_initcall(), which runs after resource
> assignments.  But I think it would be better if we could create the
> sysfs file when we assign the BAR.  Then we could get rid of the
> late_initcall() and that implicit ordering requirement.
> 
> But I haven't tried to code it up, so it's probably more complicated
> than this.  I guess ideally we would assign all the resources before
> pci_bus_add_device().  If we could do that, we could just remove
> pci_sysfs_init() and everything would just work, but I think that's a
> HUGE can of worms.
> 
> [1] https://lore.kernel.org/linux-pci/CAE9FiQWBXHgz-gWCmpWLaBOfQQJwtRZemV6Ut9GVw_KJ-dTGTA@mail.gmail.com/

I found out that pci_sysfs_init() function was introduced in kernel
version 2.6.10 by this historic commit:

https://git.kernel.org/pub/scm/linux/kernel/git/history/history.git/commit/?id=f6d553444da20cd1e44f2c4864c2d0c56c934e0a

So it was really due to PCI ROM BAR and accessing it from sysfs.

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Krzysztof Wilczyński]

Hello Pali!

Sincere apologies for taking a long time to get back to you.

On 20-11-04 17:29:31, Pali Rohár wrote:

[...]
> 
> Krzysztof, as Bjorn wrote, do you want to take this issue?
> 
[...]

Yes.  I already talked to Bjorn about this briefly, and thus I am more
than happy to take care about this.  Most definitely.

Krzysztof

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Sunday 15 November 2020 07:19:36 Krzysztof Wilczyński wrote:
> Hello Pali!
> 
> Sincere apologies for taking a long time to get back to you.
> 
> On 20-11-04 17:29:31, Pali Rohár wrote:
> 
> [...]
> > 
> > Krzysztof, as Bjorn wrote, do you want to take this issue?
> > 
> [...]
> 
> Yes.  I already talked to Bjorn about this briefly, and thus I am more
> than happy to take care about this.  Most definitely.
> 
> Krzysztof

Hello Krzysztof!

Thank you very much. I have there some patches for pci aardvard driver
which decrease boot time but trigger this race condition more often. So
they are not suitable for upstreaming yet.

Once you you have a fix for it, let me know and I could test it with my
aardvark patches.

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Petr Štetiar]

Pali Rohár <pali@kernel.org> [2020-10-07 10:12:27]:

Hi,

[adding Koen to Cc:]

> I'm hitting these race conditions randomly on pci aardvark controller
> driver- I prepared patch which speed up initialization of this driver,
> but also increase probability that it hits above race conditions :-(

it seems, that I'm able to reproduce this race condition on every boot with
5.10 on my Freescale i.MX6Q board, see the log excerpt bellow. I don't know if
this helps, but it's not happening on 5.4 kernel.

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.10.27 (ynezz@ntbk) (arm-openwrt-linux-muslgnueabi-gcc (OpenWrt GCC 8.4.0 r12719+30-84f4a783c698) 8.4.0, GNU ld (GNU Binutils) 2.34) #0 SMP Wed Apr 7 12:52:23 2021
[    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Toradex Apalis iMX6Q/D Module on Ixora Carrier Board

...

[    2.239498] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-0x010fffff]
[    2.266430] pci 0000:00:00.0: BAR 6: assigned [mem 0x01100000-0x0110ffff pref]
����#���+$HH��.274570] pci 0000:00:00.0: Max Payload Size set to  128/ 128 (was  128), Max Read Rq  128

 (this serial console hiccup during PCI initialization seems quite strange as well, happens always)

[    2.283074] sysfs: cannot create duplicate filename '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config'
[    2.293884] CPU: 1 PID: 47 Comm: kworker/u8:3 Not tainted 5.10.27 #0
[    2.300165] random: fast init done
[    2.300249] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[    2.310186] Workqueue: events_unbound async_run_entry_fn
[    2.315507] Backtrace:
[    2.317976] [<8010cc88>] (dump_backtrace) from [<8010d134>] (show_stack+0x20/0x24)
[    2.325556]  r7:813283d4 r6:60000013 r5:00000000 r4:80ec845c
[    2.331236] [<8010d114>] (show_stack) from [<805971fc>] (dump_stack+0xa4/0xb8)
[    2.338480] [<80597158>] (dump_stack) from [<803a7128>] (sysfs_warn_dup+0x68/0x74)
[    2.346058]  r7:813283d4 r6:80af0dfc r5:812f48f0 r4:81afa000
[    2.351726] [<803a70c0>] (sysfs_warn_dup) from [<803a6c90>] (sysfs_add_file_mode_ns+0x100/0x1cc)
[    2.360518]  r7:813283d4 r6:812f48f0 r5:80b4299c r4:ffffffef
[    2.366187] [<803a6b90>] (sysfs_add_file_mode_ns) from [<803a6fe8>] (sysfs_create_bin_file+0x94/0x9c)
[    2.375411]  r6:81eb8078 r5:80b4299c r4:00000000
[    2.380043] [<803a6f54>] (sysfs_create_bin_file) from [<805da848>] (pci_create_sysfs_dev_files+0x58/0x2cc)
[    2.389701]  r6:81eb8000 r5:81eb8078 r4:81eb8000
[    2.394341] [<805da7f0>] (pci_create_sysfs_dev_files) from [<805cba98>] (pci_bus_add_device+0x34/0x90)
[    2.403659]  r10:80b45d88 r9:81818810 r8:81328200 r7:813283d4 r6:8190c000 r5:81eb8078
[    2.411490]  r4:81eb8000
[    2.414034] [<805cba64>] (pci_bus_add_device) from [<805cbb30>] (pci_bus_add_devices+0x3c/0x80)
[    2.421744] random: crng init done
[    2.422737]  r5:8190c014 r4:81eb8000
[    2.429720] [<805cbaf4>] (pci_bus_add_devices) from [<805cf898>] (pci_host_probe+0x50/0xa0)
[    2.438078]  r7:813283d4 r6:8190c000 r5:8190c00c r4:00000000
[    2.443753] [<805cf848>] (pci_host_probe) from [<805eeb20>] (dw_pcie_host_init+0x1d0/0x414)
[    2.452111]  r7:813283d4 r6:81328058 r5:00000200 r4:00000000
[    2.457780] [<805ee950>] (dw_pcie_host_init) from [<805ef5a8>] (imx6_pcie_probe+0x38c/0x69c)
[    2.466226]  r10:81226180 r9:ef0205c4 r8:81818800 r7:81328040 r6:81328040 r5:81818810
[    2.474060]  r4:00000020
[    2.476615] [<805ef21c>] (imx6_pcie_probe) from [<8065e858>] (platform_drv_probe+0x58/0xa8)
[    2.484977]  r10:80ec9f78 r9:00000000 r8:80f160a8 r7:00000000 r6:80ec9f78 r5:00000000
[    2.492809]  r4:81818810
[    2.495357] [<8065e800>] (platform_drv_probe) from [<8065c0a0>] (really_probe+0x128/0x534)
[    2.503627]  r7:00000000 r6:80f5b8c4 r5:81818810 r4:80f5b8d4
[    2.509296] [<8065bf78>] (really_probe) from [<8065c700>] (driver_probe_device+0x88/0x200)
[    2.517570]  r10:00000000 r9:80f0bb60 r8:00000000 r7:80f160a8 r6:80ec9f78 r5:80ec9f78
[    2.525401]  r4:81818810
[    2.527946] [<8065c678>] (driver_probe_device) from [<8065c904>] (__driver_attach_async_helper+0x8c/0xb4)
[    2.537521]  r9:80f0bb60 r8:00000000 r7:8104d000 r6:80ec9f78 r5:80f25010 r4:81818810
[    2.545273] [<8065c878>] (__driver_attach_async_helper) from [<8015b930>] (async_run_entry_fn+0x58/0x1bc)
[    2.554843]  r6:819fb480 r5:80f25010 r4:819fb490
[    2.559479] [<8015b8d8>] (async_run_entry_fn) from [<8015114c>] (process_one_work+0x238/0x5ac)
[    2.568099]  r8:00000000 r7:8104d000 r6:81048400 r5:8127a080 r4:819fb490
[    2.574811] [<80150f14>] (process_one_work) from [<8015152c>] (worker_thread+0x6c/0x5c0)
[    2.582909]  r10:81048400 r9:80e03d00 r8:81048418 r7:00000088 r6:81048400 r5:8127a094
[    2.590742]  r4:8127a080
[    2.593290] [<801514c0>] (worker_thread) from [<80158168>] (kthread+0x174/0x178)
[    2.600694]  r10:8127a080 r9:812e3024 r8:8116fe74 r7:813c0000 r6:00000000 r5:8127b040
[    2.608527]  r4:812e3000
[    2.611073] [<80157ff4>] (kthread) from [<80100148>] (ret_from_fork+0x14/0x2c)
[    2.618302] Exception stack(0x813c1fb0 to 0x813c1ff8)
[    2.623362] 1fa0:                                     00000000 00000000 00000000 00000000
[    2.631548] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[    2.639731] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[    2.646354]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80157ff4
[    2.654187]  r4:8127b040
[    2.657157] pcieport 0000:00:00.0: PME: Signaling with IRQ 316
[    2.674770] VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
[    2.686264] Freeing unused kernel memory: 1024K

Complete serial console log http://sprunge.us/wCe6zs

Cheers,

Petr

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Thursday 16 July 2020 13:04:23 Pali Rohár wrote:
> Hello Bjorn!
> 
> I see following error message in dmesg which looks like a race condition:
> 
> sysfs: cannot create duplicate filename '/devices/platform/soc/d0070000.pcie/pci0000:00/0000:00:00.0/config'
> 
> I looked at it deeper and found out that in PCI subsystem code is race
> condition between pci_bus_add_device() and pci_sysfs_init() calls. Both
> of these functions calls pci_create_sysfs_dev_files() and calling this
> function more times for same pci device throws above error message.
> 
> There can be two different race conditions:
> 
> 1. pci_bus_add_device() called pcibios_bus_add_device() or
> pci_fixup_device() but have not called pci_create_sysfs_dev_files() yet.
> Meanwhile pci_sysfs_init() is running and pci_create_sysfs_dev_files()
> was called for newly registered device. In this case function
> pci_create_sysfs_dev_files() is called two times, ones from
> pci_bus_add_device() and once from pci_sysfs_init().
> 
> 2. pci_sysfs_init() is called. It first sets sysfs_initialized to 1
> which unblock calling pci_create_sysfs_dev_files(). Then another bus
> registers new PCI device and calls pci_bus_add_device() which calls
> pci_create_sysfs_dev_files() and registers sysfs files. Function
> pci_sysfs_init() continues execution and calls function
> pci_create_sysfs_dev_files() also for this newly registered device. So
> pci_create_sysfs_dev_files() is again called two times.
> 
> 
> I workaround both race conditions I created following hack patch. After
> applying it I'm not getting that 'sysfs: cannot create duplicate filename'
> error message anymore.

Scratch this hack patch, it contains another new race condition.

The only way how to get rid of this race condition is either to protect
whole "sysfs_initialized" variable by mutex or by completely removing
"sysfs_initialized" variable and therefore also removing function
pci_create_sysfs_dev_files(). I'm for second variant.

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

On Wednesday 07 April 2021 16:25:46 Petr Štetiar wrote:
> Pali Rohár <pali@kernel.org> [2020-10-07 10:12:27]:
> 
> Hi,
> 
> [adding Koen to Cc:]
> 
> > I'm hitting these race conditions randomly on pci aardvark controller
> > driver- I prepared patch which speed up initialization of this driver,
> > but also increase probability that it hits above race conditions :-(
> 
> it seems, that I'm able to reproduce this race condition on every boot with
> 5.10 on my Freescale i.MX6Q board, see the log excerpt bellow. I don't know if
> this helps, but it's not happening on 5.4 kernel.

Hello! This is same race condition which I described in my original
report. Good to know that other people can reproduce it too!

> [    0.000000] Booting Linux on physical CPU 0x0
> [    0.000000] Linux version 5.10.27 (ynezz@ntbk) (arm-openwrt-linux-muslgnueabi-gcc (OpenWrt GCC 8.4.0 r12719+30-84f4a783c698) 8.4.0, GNU ld (GNU Binutils) 2.34) #0 SMP Wed Apr 7 12:52:23 2021
> [    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
> [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> [    0.000000] OF: fdt: Machine model: Toradex Apalis iMX6Q/D Module on Ixora Carrier Board
> 
> ...
> 
> [    2.239498] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-0x010fffff]
> [    2.266430] pci 0000:00:00.0: BAR 6: assigned [mem 0x01100000-0x0110ffff pref]
> ����#���+$HH��.274570] pci 0000:00:00.0: Max Payload Size set to  128/ 128 (was  128), Max Read Rq  128
> 
>  (this serial console hiccup during PCI initialization seems quite strange as well, happens always)

I'm seeing similar garbage on UART output when such thing happen. But I
suspect that this is the issue when doing serialization of more parallel
messages print by kernel. Nothing relevant to PCI.

But running 'dmesg' after full bootup can show also these lost messages.

> [    2.283074] sysfs: cannot create duplicate filename '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config'
> [    2.293884] CPU: 1 PID: 47 Comm: kworker/u8:3 Not tainted 5.10.27 #0
> [    2.300165] random: fast init done
> [    2.300249] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [    2.310186] Workqueue: events_unbound async_run_entry_fn

And this is important information! Device is registered by some async
workqueue. When I tried to use my (private) patch which speed by
aardvark initialization by putting init code into separate worker then
probability of hitting this race condition increased to about 90%. So
same situation as yours, it was called from async workqueue.

But now with 5.12-rc kernel I'm not able to reproduce it because
something changed in kernel and kernel schedule this "racy" worker long
after race condition may happen.

So it needs perfect timing and seems that one important thing is to call
pci_bus_add_device() function from separate worker.

> [    2.315507] Backtrace:
> [    2.317976] [<8010cc88>] (dump_backtrace) from [<8010d134>] (show_stack+0x20/0x24)
> [    2.325556]  r7:813283d4 r6:60000013 r5:00000000 r4:80ec845c
> [    2.331236] [<8010d114>] (show_stack) from [<805971fc>] (dump_stack+0xa4/0xb8)
> [    2.338480] [<80597158>] (dump_stack) from [<803a7128>] (sysfs_warn_dup+0x68/0x74)
> [    2.346058]  r7:813283d4 r6:80af0dfc r5:812f48f0 r4:81afa000
> [    2.351726] [<803a70c0>] (sysfs_warn_dup) from [<803a6c90>] (sysfs_add_file_mode_ns+0x100/0x1cc)
> [    2.360518]  r7:813283d4 r6:812f48f0 r5:80b4299c r4:ffffffef
> [    2.366187] [<803a6b90>] (sysfs_add_file_mode_ns) from [<803a6fe8>] (sysfs_create_bin_file+0x94/0x9c)
> [    2.375411]  r6:81eb8078 r5:80b4299c r4:00000000
> [    2.380043] [<803a6f54>] (sysfs_create_bin_file) from [<805da848>] (pci_create_sysfs_dev_files+0x58/0x2cc)
> [    2.389701]  r6:81eb8000 r5:81eb8078 r4:81eb8000
> [    2.394341] [<805da7f0>] (pci_create_sysfs_dev_files) from [<805cba98>] (pci_bus_add_device+0x34/0x90)
> [    2.403659]  r10:80b45d88 r9:81818810 r8:81328200 r7:813283d4 r6:8190c000 r5:81eb8078
> [    2.411490]  r4:81eb8000
> [    2.414034] [<805cba64>] (pci_bus_add_device) from [<805cbb30>] (pci_bus_add_devices+0x3c/0x80)
> [    2.421744] random: crng init done
> [    2.422737]  r5:8190c014 r4:81eb8000
> [    2.429720] [<805cbaf4>] (pci_bus_add_devices) from [<805cf898>] (pci_host_probe+0x50/0xa0)
> [    2.438078]  r7:813283d4 r6:8190c000 r5:8190c00c r4:00000000
> [    2.443753] [<805cf848>] (pci_host_probe) from [<805eeb20>] (dw_pcie_host_init+0x1d0/0x414)
> [    2.452111]  r7:813283d4 r6:81328058 r5:00000200 r4:00000000
> [    2.457780] [<805ee950>] (dw_pcie_host_init) from [<805ef5a8>] (imx6_pcie_probe+0x38c/0x69c)
> [    2.466226]  r10:81226180 r9:ef0205c4 r8:81818800 r7:81328040 r6:81328040 r5:81818810
> [    2.474060]  r4:00000020
> [    2.476615] [<805ef21c>] (imx6_pcie_probe) from [<8065e858>] (platform_drv_probe+0x58/0xa8)
> [    2.484977]  r10:80ec9f78 r9:00000000 r8:80f160a8 r7:00000000 r6:80ec9f78 r5:00000000
> [    2.492809]  r4:81818810
> [    2.495357] [<8065e800>] (platform_drv_probe) from [<8065c0a0>] (really_probe+0x128/0x534)
> [    2.503627]  r7:00000000 r6:80f5b8c4 r5:81818810 r4:80f5b8d4
> [    2.509296] [<8065bf78>] (really_probe) from [<8065c700>] (driver_probe_device+0x88/0x200)
> [    2.517570]  r10:00000000 r9:80f0bb60 r8:00000000 r7:80f160a8 r6:80ec9f78 r5:80ec9f78
> [    2.525401]  r4:81818810
> [    2.527946] [<8065c678>] (driver_probe_device) from [<8065c904>] (__driver_attach_async_helper+0x8c/0xb4)
> [    2.537521]  r9:80f0bb60 r8:00000000 r7:8104d000 r6:80ec9f78 r5:80f25010 r4:81818810
> [    2.545273] [<8065c878>] (__driver_attach_async_helper) from [<8015b930>] (async_run_entry_fn+0x58/0x1bc)
> [    2.554843]  r6:819fb480 r5:80f25010 r4:819fb490
> [    2.559479] [<8015b8d8>] (async_run_entry_fn) from [<8015114c>] (process_one_work+0x238/0x5ac)
> [    2.568099]  r8:00000000 r7:8104d000 r6:81048400 r5:8127a080 r4:819fb490
> [    2.574811] [<80150f14>] (process_one_work) from [<8015152c>] (worker_thread+0x6c/0x5c0)
> [    2.582909]  r10:81048400 r9:80e03d00 r8:81048418 r7:00000088 r6:81048400 r5:8127a094
> [    2.590742]  r4:8127a080
> [    2.593290] [<801514c0>] (worker_thread) from [<80158168>] (kthread+0x174/0x178)
> [    2.600694]  r10:8127a080 r9:812e3024 r8:8116fe74 r7:813c0000 r6:00000000 r5:8127b040
> [    2.608527]  r4:812e3000
> [    2.611073] [<80157ff4>] (kthread) from [<80100148>] (ret_from_fork+0x14/0x2c)
> [    2.618302] Exception stack(0x813c1fb0 to 0x813c1ff8)
> [    2.623362] 1fa0:                                     00000000 00000000 00000000 00000000
> [    2.631548] 1fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> [    2.639731] 1fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [    2.646354]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80157ff4
> [    2.654187]  r4:8127b040
> [    2.657157] pcieport 0000:00:00.0: PME: Signaling with IRQ 316
> [    2.674770] VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
> [    2.686264] Freeing unused kernel memory: 1024K
> 
> Complete serial console log http://sprunge.us/wCe6zs

Could you run 'dmesg' and provide its output? So also missing / garbage
messages would be visible.

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Petr Štetiar]

Pali Rohár <pali@kernel.org> [2021-04-07 16:51:47]:

> Could you run 'dmesg' and provide its output? So also missing / garbage
> messages would be visible.

Adding it inline for archives. It's log from serial console, with output of dmesg at the
bottom so one can compare if needed.

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.10.27 (ynezz@ntbk) (arm-openwrt-linux-muslgnueabi-gcc (OpenWrt GCC 8.4.0 r12719+30-84f4a783c698) 8.4.0, GNU ld (GNU Binutils) 2.34) #0 SMP Wed Apr 7 12:52:23 2021
[    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Toradex Apalis iMX6Q/D Module on Ixora Carrier Board
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Ignoring RAM at 0x80000000-0x90000000
[    0.000000] Consider using a HIGHMEM enabled kernel.
[    0.000000] Zone ranges:
[    0.000000]   Normal   [mem 0x0000000010000000-0x000000007fffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000010000000-0x000000007fffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000010000000-0x000000007fffffff]
[    0.000000] percpu: Embedded 19 pages/cpu s47628 r8192 d22004 u77824
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 454720
[    0.000000] Kernel command line: earlyprintk console=ttymxc0,115200n8 root=PARTUUID=5452574f-02 rootfstype=squashfs rootwait pci=nomsi
[    0.000000] Dentry cache hash table entries: 262144 (order: 8, 1048576 bytes, linear)
[    0.000000] Inode-cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 1802104K/1835008K available (9040K kernel code, 1170K rwdata, 2328K rodata, 1024K init, 242K bss, 32904K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 31336 entries in 62 pages
[    0.000000] ftrace: allocated 62 pages with 5 groups
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] L2C-310 errata 752271 769419 enabled
[    0.000000] L2C-310 enabling early BRESP for Cortex-A9
[    0.000000] L2C-310 full line of zeros enabled for Cortex-A9
[    0.000000] L2C-310 ID prefetch enabled, offset 16 lines
[    0.000000] L2C-310 dynamic clock gating enabled, standby mode enabled
[    0.000000] L2C-310 cache controller enabled, 16 ways, 1024 kB
[    0.000000] L2C-310: CACHE_ID 0x410000c7, AUX_CTRL 0x76470001
[    0.000000] random: get_random_bytes called from start_kernel+0x3e0/0x5a0 with crng_init=0
[    0.000000] Switching to timer-based delay loop, resolution 333ns
[    0.000008] sched_clock: 32 bits at 3000kHz, resolution 333ns, wraps every 715827882841ns
[    0.000029] clocksource: mxc_timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 637086815595 ns
[    0.001279] Console: colour dummy device 80x30
[    0.001318] Calibrating delay loop (skipped), value calculated using timer frequency.. 6.00 BogoMIPS (lpj=30000)
[    0.001340] pid_max: default: 32768 minimum: 301
[    0.001548] Mount-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
[    0.001588] Mountpoint-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
[    0.002484] CPU: Testing write buffer coherency: ok
[    0.002522] CPU0: Spectre v2: using BPIALL workaround
[    0.002789] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003686] Setting up static identity map for 0x10100000 - 0x10100060
[    0.003845] rcu: Hierarchical SRCU implementation.
[    0.004844] smp: Bringing up secondary CPUs ...
[    0.005689] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.005698] CPU1: Spectre v2: using BPIALL workaround
[    0.006667] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.006676] CPU2: Spectre v2: using BPIALL workaround
[    0.007606] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007615] CPU3: Spectre v2: using BPIALL workaround
[    0.007755] smp: Brought up 1 node, 4 CPUs
[    0.007770] SMP: Total of 4 processors activated (24.00 BogoMIPS).
[    0.007780] CPU: All CPU(s) started in SVC mode.
[    0.017479] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
[    0.017696] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.017731] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.017995] pinctrl core: initialized pinctrl subsystem
[    0.019710] NET: Registered protocol family 16
[    0.021665] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.023180] thermal_sys: Registered thermal governor 'step_wise'
[    0.023660] CPU identified as i.MX6Q, silicon rev 1.5
[    0.245571] vdd1p1: supplied by regulator-dummy
[    0.254210] vdd3p0: supplied by regulator-dummy
[    0.262785] vdd2p5: supplied by regulator-dummy
[    0.271321] vddarm: supplied by regulator-dummy
[    0.279909] vddpu: supplied by regulator-dummy
[    0.288419] vddsoc: supplied by regulator-dummy
[    0.628532] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.628554] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.628861] debugfs: Directory 'dummy-iomuxc-gpr@20e0000' with parent 'regmap' already present!
[    0.629263] imx6q-pinctrl 20e0000.pinctrl: initialized IMX pinctrl driver
[    0.647595] Kprobes globally optimized
[    0.650233] cryptd: max_cpu_qlen set to 1000
[    0.666849] mxs-dma 110000.dma-apbh: initialized
[    0.669973] usb_host_vbus: supplied by usb_host_vbus_hub
[    0.670896] SCSI subsystem initialized
[    0.671797] usbcore: registered new interface driver usbfs
[    0.671910] usbcore: registered new interface driver hub
[    0.671999] usbcore: registered new device driver usb
[    0.674185] i2c i2c-0: IMX I2C adapter registered
[    0.676657] i2c i2c-2: IMX I2C adapter registered
[    0.677730] i2c i2c-1: IMX I2C adapter registered
[    0.678202] pps_core: LinuxPPS API ver. 1 registered
[    0.678217] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.678258] PTP clock support registered
[    0.680434] clocksource: Switched to clocksource mxc_timer1
[    0.800167] NET: Registered protocol family 2
[    0.801060] tcp_listen_portaddr_hash hash table entries: 1024 (order: 1, 12288 bytes, linear)
[    0.801141] TCP established hash table entries: 16384 (order: 4, 65536 bytes, linear)
[    0.801432] TCP bind hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.802002] TCP: Hash tables configured (established 16384 bind 16384)
[    0.802377] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
[    0.802490] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
[    0.802831] NET: Registered protocol family 1
[    0.802876] PCI: CLS 0 bytes, default 64
[    0.803583] hw perfevents: no interrupt-affinity property for /pmu, guessing.
[    0.803842] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
[    0.809163] workingset: timestamp_bits=14 max_order=19 bucket_order=5
[    0.813910] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.926864] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    0.929303] imx6q-pcie 1ffc000.pcie: host bridge /soc/pcie@1ffc000 ranges:
[    0.929370] imx6q-pcie 1ffc000.pcie:       IO 0x0001f80000..0x0001f8ffff -> 0x0000000000
[    0.929411] imx6q-pcie 1ffc000.pcie:      MEM 0x0001000000..0x0001efffff -> 0x0001000000
[    0.936834] imx-sdma 20ec000.sdma: loaded firmware 3.5
[    0.938840] pfuze100-regulator 2-0008: Full layer: 1, Metal layer: 1
[    0.939545] pfuze100-regulator 2-0008: FAB: 0, FIN: 0
[    0.939560] pfuze100-regulator 2-0008: pfuze100 found.
[    0.956572] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled
[    0.957946] 2020000.serial: ttymxc0 at MMIO 0x2020000 (irq = 34, base_baud = 5000000) is a IMX
[    1.670939] printk: console [ttymxc0] enabled
[    1.676645] 21e8000.serial: ttymxc1 at MMIO 0x21e8000 (irq = 81, base_baud = 5000000) is a IMX
[    1.686125] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 82, base_baud = 5000000) is a IMX
[    1.695541] 21f4000.serial: ttymxc4 at MMIO 0x21f4000 (irq = 83, base_baud = 5000000) is a IMX
[    1.711037] loop: module loaded
[    1.714198] Loading iSCSI transport class v2.0-870.
[    1.720904] ahci-imx 2200000.sata: fsl,transmit-level-mV not specified, using 00000024
[    1.728838] ahci-imx 2200000.sata: fsl,transmit-boost-mdB not specified, using 00000480
[    1.736873] ahci-imx 2200000.sata: fsl,transmit-atten-16ths not specified, using 00002000
[    1.745076] ahci-imx 2200000.sata: fsl,receive-eq-mdB not specified, using 05000000
[    1.752856] ahci-imx 2200000.sata: supply ahci not found, using dummy regulator
[    1.760380] ahci-imx 2200000.sata: supply phy not found, using dummy regulator
[    1.767721] ahci-imx 2200000.sata: supply target not found, using dummy regulator
[    1.778076] ahci-imx 2200000.sata: SSS flag set, parallel bus scan disabled
[    1.785108] ahci-imx 2200000.sata: AHCI 0001.0300 32 slots 1 ports 3 Gbps 0x1 impl platform mode
[    1.793935] ahci-imx 2200000.sata: flags: ncq sntf stag pm led clo only pmp pio slum part ccc apst
[    1.804523] scsi host0: ahci-imx
[    1.808138] ata1: SATA max UDMA/133 mmio [mem 0x02200000-0x02203fff] port 0x100 irq 86
[    1.818261] libphy: Fixed MDIO Bus: probed
[    1.836498] pps pps0: new PPS source ptp0
[    1.842688] libphy: fec_enet_mii_bus: probed
[    1.848952] fec 2188000.ethernet eth0: registered PHC device 0
[    1.855343] e1000e: Intel(R) PRO/1000 Network Driver
[    1.860315] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    1.866373] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.872957] ehci-pci: EHCI PCI platform driver
[    1.877464] ehci-mxc: Freescale On-Chip EHCI Host driver
[    1.886285] rtc-ds1307 0-0068: oscillator failed, set time!
[    1.892036] rtc-ds1307 0-0068: registered as rtc0
[    1.898144] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
[    1.905241] i2c /dev entries driver
[    1.911218] sdhci: Secure Digital Host Controller Interface driver
[    1.917410] sdhci: Copyright(c) Pierre Ossman
[    1.921792] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.928836] sdhci-esdhc-imx 2194000.mmc: Got CD GPIO
[    1.929555] caam 2100000.crypto: Entropy delay = 3200
[    1.966821] mmc2: SDHCI controller on 2198000.mmc [2198000.mmc] using ADMA
[    1.974375] mmc1: SDHCI controller on 2194000.mmc [2194000.mmc] using ADMA
[    1.999674] caam 2100000.crypto: Instantiated RNG4 SH0
[    2.040446] imx6q-pcie 1ffc000.pcie: Phy link never came up
[    2.049259] imx6q-pcie 1ffc000.pcie: PCI host bridge to bus 0000:00
[    2.055566] pci_bus 0000:00: root bus resource [bus 00-ff]
[    2.060434] caam 2100000.crypto: Instantiated RNG4 SH1
[    2.061088] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    2.066207] caam 2100000.crypto: device ID = 0x0a16010000000000 (Era 4)
[    2.072406] pci_bus 0000:00: root bus resource [mem 0x01000000-0x01efffff]
[    2.076096] mmc2: new DDR MMC card at address 0001
[    2.077087] mmcblk2: mmc2:0001 BIWIN  7.28 GiB
[    2.077714] mmcblk2boot0: mmc2:0001 BIWIN  partition 1 4.00 MiB
[    2.078331] mmcblk2boot1: mmc2:0001 BIWIN  partition 2 4.00 MiB
[    2.078464] mmcblk2rpmb: mmc2:0001 BIWIN  partition 3 4.00 MiB, chardev (248:0)
[    2.079029] caam 2100000.crypto: job rings = 2, qi = 0
[    2.079769]  mmcblk2: p1 p2
[    2.085973] pci 0000:00:00.0: [16c3:abcd] type 01 class 0x060400
[    2.098373] caam algorithms registered in /proc/crypto
[    2.101276] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]
[    2.108603] caam 2100000.crypto: registering rng-caam
[    2.114480] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]
[    2.124125] NET: Registered protocol family 10
[    2.128468] pci 0000:00:00.0: Limiting cfg_size to 512
[    2.134736] Segment Routing with IPv6
[    2.139879] pci 0000:00:00.0: imx6_pcie_quirk+0x0/0x84 took 11125 usecs
[    2.142319] ata1: SATA link down (SStatus 0 SControl 300)
[    2.142367] ahci-imx 2200000.sata: no device found, disabling link.
[    2.142376] ahci-imx 2200000.sata: pass ahci_imx..hotplug=1 to enable hotplug
[    2.145016] NET: Registered protocol family 17
[    2.151684] pci 0000:00:00.0: supports D1
[    2.156289] 8021q: 802.1Q VLAN Support v1.8
[    2.161238] pci 0000:00:00.0: PME# supported from D0 D1 D3hot D3cold
[    2.165900] PCI: bus0: Fast back to back transfers disabled
[    2.173156] Registering SWP/SWPB emulation handler
[    2.181426] PCI: bus1: Fast back to back transfers enabled
[    2.185540] Key type ._fscrypt registered
[    2.190445] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-0x010fffff]
[    2.194840] Key type .fscrypt registered
[    2.198843] pci 0000:00:00.0: BAR 6: assigned [mem 0x01100000-0x0110ffff pref]
[    2.203025] Key type fscrypt-provisioning registered
[    2.207714] Key type encrypted registered
[    2.209408] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
[    2.239936] imx_thermal 20c8000.anatop:tempmon: Industrial CPU temperature grade - max:105C critical:100C passive:95C
[    2.240101] pci 0000:00:00.0: Max Payload Size set to  128/ 128 (was  128), Max Read Rq  128
[    2.280656] sysfs: cannot create duplicate filename '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config'
[    2.291471] CPU: 1 PID: 46 Comm: kworker/u8:3 Not tainted 5.10.27 #0
[    2.297832] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[    2.303545] random: fast init done
[    2.304384] Workqueue: events_unbound async_run_entry_fn
[    2.313090] Backtrace:
[    2.315558] [<8010cc88>] (dump_backtrace) from [<8010d134>] (show_stack+0x20/0x24)
[    2.323136]  r7:813285d4 r6:60000013 r5:00000000 r4:80ec845c
[    2.328815] [<8010d114>] (show_stack) from [<805971fc>] (dump_stack+0xa4/0xb8)
[    2.336058] [<80597158>] (dump_stack) from [<803a7128>] (sysfs_warn_dup+0x68/0x74)
[    2.343636]  r7:813285d4 r6:80af0dfc r5:812fc8f0 r4:81bcb000
[    2.349305] [<803a70c0>] (sysfs_warn_dup) from [<803a6c90>] (sysfs_add_file_mode_ns+0x100/0x1cc)
[    2.358098]  r7:813285d4 r6:812fc8f0 r5:80b4299c r4:ffffffef
[    2.363765] [<803a6b90>] (sysfs_add_file_mode_ns) from [<803a6fe8>] (sysfs_create_bin_file+0x94/0x9c)
[    2.372991]  r6:81e68078 r5:80b4299c r4:00000000
[    2.377626] [<803a6f54>] (sysfs_create_bin_file) from [<805da848>] (pci_create_sysfs_dev_files+0x58/0x2cc)
[    2.387285]  r6:81e68000 r5:81e68078 r4:81e68000
[    2.391923] [<805da7f0>] (pci_create_sysfs_dev_files) from [<805cba98>] (pci_bus_add_device+0x34/0x90)
[    2.401237]  r10:80b45d88 r9:81818810 r8:81328400 r7:813285d4 r6:81bd8000 r5:81e68078
[    2.409071]  r4:81e68000
[    2.411615] [<805cba64>] (pci_bus_add_device) from [<805cbb30>] (pci_bus_add_devices+0x3c/0x80)
[    2.420318]  r5:81bd8014 r4:81e68000
[    2.423905] [<805cbaf4>] (pci_bus_add_devices) from [<805cf898>] (pci_host_probe+0x50/0xa0)
[    2.425126] random: crng init done
[    2.432263]  r7:813285d4 r6:81bd8000 r5:81bd800c r4:00000000
[    2.432279] [<805cf848>] (pci_host_probe) from [<805eeb20>] (dw_pcie_host_init+0x1d0/0x414)
[    2.432294]  r7:813285d4 r6:81328258 r5:00000200 r4:00000000
[    2.455360] [<805ee950>] (dw_pcie_host_init) from [<805ef5a8>] (imx6_pcie_probe+0x38c/0x69c)
[    2.463807]  r10:81226180 r9:ef0205c4 r8:81818800 r7:81328240 r6:81328240 r5:81818810
[    2.471640]  r4:00000020
[    2.474197] [<805ef21c>] (imx6_pcie_probe) from [<8065e858>] (platform_drv_probe+0x58/0xa8)
[    2.482557]  r10:80ec9f78 r9:00000000 r8:80f160a8 r7:00000000 r6:80ec9f78 r5:00000000
[    2.490390]  r4:81818810
[    2.492937] [<8065e800>] (platform_drv_probe) from [<8065c0a0>] (really_probe+0x128/0x534)
[    2.501207]  r7:00000000 r6:80f5b8c4 r5:81818810 r4:80f5b8d4
[    2.506877] [<8065bf78>] (really_probe) from [<8065c700>] (driver_probe_device+0x88/0x200)
[    2.515148]  r10:00000000 r9:80f0bb60 r8:00000000 r7:80f160a8 r6:80ec9f78 r5:80ec9f78
[    2.522981]  r4:81818810
[    2.525526] [<8065c678>] (driver_probe_device) from [<8065c904>] (__driver_attach_async_helper+0x8c/0xb4)
[    2.535100]  r9:80f0bb60 r8:00000000 r7:8104d000 r6:80ec9f78 r5:80f25010 r4:81818810
[    2.542853] [<8065c878>] (__driver_attach_async_helper) from [<8015b930>] (async_run_entry_fn+0x58/0x1bc)
[    2.552425]  r6:81a758c0 r5:80f25010 r4:81a758d0
[    2.557060] [<8015b8d8>] (async_run_entry_fn) from [<8015114c>] (process_one_work+0x238/0x5ac)
[    2.565681]  r8:00000000 r7:8104d000 r6:81048400 r5:8127a080 r4:81a758d0
[    2.572392] [<80150f14>] (process_one_work) from [<8015152c>] (worker_thread+0x6c/0x5c0)
[    2.580493]  r10:81048400 r9:80e03d00 r8:81048418 r7:00000088 r6:81048400 r5:8127a094
[    2.588325]  r4:8127a080
[    2.590874] [<801514c0>] (worker_thread) from [<80158168>] (kthread+0x174/0x178)
[    2.598278]  r10:8127a080 r9:81217fe4 r8:8116fe74 r7:81364000 r6:00000000 r5:8127b040
[    2.606111]  r4:81217fc0
[    2.608654] [<80157ff4>] (kthread) from [<80100148>] (ret_from_fork+0x14/0x2c)
[    2.615881] Exception stack(0x81365fb0 to 0x81365ff8)
[    2.620941] 5fa0:                                     00000000 00000000 00000000 00000000
[    2.629127] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[    2.637311] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[    2.643934]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80157ff4
[    2.651766]  r4:8127b040
[    2.654741] pcieport 0000:00:00.0: PME: Signaling with IRQ 316
[    2.672706] VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
[    2.684075] Freeing unused kernel memory: 1024K
[    2.710947] Run /sbin/init as init process
[    2.959976] init: Console is alive
[    2.963628] init: - watchdog -
[    3.364282] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    3.418956] gpio-keys gpio-keys: does not support key code:143
[    3.427977] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    3.441567] init: - preinit -
[    4.224669] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
Press the [f] key and hit [enter] to enter failsafe mode
Press the [1], [2], [3] or [4] key and hit [enter] to select the debug level
[    8.560835] EXT4-fs (loop0): recovery complete
[    8.566782] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[    8.576293] mount_root: switching to ext4 overlay
[    8.824878] EXT4-fs (mmcblk2p1): mounted filesystem without journal. Opts: (null)
[    8.841054] urandom-seed: Seeding with /etc/urandom.seed
[    8.957052] procd: - early -
[    8.960004] procd: - watchdog -
[    9.553020] procd: - watchdog -
[    9.556647] procd: - ubus -
[    9.719723] procd: - init -
Please press Enter to activate this console.
[   10.135757] kmodloader: loading kernel modules from /etc/modules.d/*
[   10.147710] urngd: v1.0.2 started.
[   10.158876] can: controller area network core
[   10.163463] NET: Registered protocol family 29
[   10.169546] CAN device driver interface
[   10.174395] can: raw protocol
[   10.510803] sps30 0-0069: failed to reset device
[   10.518325] usbcore: registered new interface driver usbserial_generic
[   10.524997] usbserial: USB Serial support registered for generic
[   10.537468] xt_time: kernel timezone is -0000
[   10.560920] usbcore: registered new interface driver option
[   10.566594] usbserial: USB Serial support registered for GSM modem (1-port)
[   10.580628] kmodloader: done loading kernel modules from /etc/modules.d/*
[   15.264668] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
[   15.280953] br-lan: port 1(eth0) entered blocking state
[   15.286194] br-lan: port 1(eth0) entered disabled state
[   15.291801] device eth0 entered promiscuous mode



BusyBox v1.33.0 () built-in shell (ash)

  _______                     ________        __
 |       |.-----.-----.-----.|  |  |  |.----.|  |_
 |   -   ||  _  |  -__|     ||  |  |  ||   _||   _|
 |_______||   __|_____|__|__||________||__|  |____|
          |__| W I R E L E S S   F R E E D O M
 -----------------------------------------------------
 OpenWrt SNAPSHOT, r16433+39-e48c6400e477
 -----------------------------------------------------
=== WARNING! =====================================
There is no root password defined on this device!
Use the "passwd" command to set up a new password
in order to prevent unauthorized SSH logins.
--------------------------------------------------
root@OpenWrt:/# dmesg
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.10.27 (ynezz@ntbk) (arm-openwrt-linux-muslgnueabi-gcc (OpenWrt GCC 8.4.0 r12719+30-84f4a783c698) 8.4.0, GNU ld (GNU Binutils) 2.34) #0 SMP Wed Apr 7 12:52:23 2021
[    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Toradex Apalis iMX6Q/D Module on Ixora Carrier Board
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Ignoring RAM at 0x80000000-0x90000000
[    0.000000] Consider using a HIGHMEM enabled kernel.
[    0.000000] Zone ranges:
[    0.000000]   Normal   [mem 0x0000000010000000-0x000000007fffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000010000000-0x000000007fffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000010000000-0x000000007fffffff]
[    0.000000] On node 0 totalpages: 458752
[    0.000000]   Normal zone: 4032 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 458752 pages, LIFO batch:63
[    0.000000] percpu: Embedded 19 pages/cpu s47628 r8192 d22004 u77824
[    0.000000] pcpu-alloc: s47628 r8192 d22004 u77824 alloc=19*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 454720
[    0.000000] Kernel command line: earlyprintk console=ttymxc0,115200n8 root=PARTUUID=5452574f-02 rootfstype=squashfs rootwait pci=nomsi
[    0.000000] Dentry cache hash table entries: 262144 (order: 8, 1048576 bytes, linear)
[    0.000000] Inode-cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 1802104K/1835008K available (9040K kernel code, 1170K rwdata, 2328K rodata, 1024K init, 242K bss, 32904K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 31336 entries in 62 pages
[    0.000000] ftrace: allocated 62 pages with 5 groups
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] L2C-310 errata 752271 769419 enabled
[    0.000000] L2C-310 enabling early BRESP for Cortex-A9
[    0.000000] L2C-310 full line of zeros enabled for Cortex-A9
[    0.000000] L2C-310 ID prefetch enabled, offset 16 lines
[    0.000000] L2C-310 dynamic clock gating enabled, standby mode enabled
[    0.000000] L2C-310 cache controller enabled, 16 ways, 1024 kB
[    0.000000] L2C-310: CACHE_ID 0x410000c7, AUX_CTRL 0x76470001
[    0.000000] random: get_random_bytes called from start_kernel+0x3e0/0x5a0 with crng_init=0
[    0.000000] Switching to timer-based delay loop, resolution 333ns
[    0.000008] sched_clock: 32 bits at 3000kHz, resolution 333ns, wraps every 715827882841ns
[    0.000029] clocksource: mxc_timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 637086815595 ns
[    0.001279] Console: colour dummy device 80x30
[    0.001318] Calibrating delay loop (skipped), value calculated using timer frequency.. 6.00 BogoMIPS (lpj=30000)
[    0.001340] pid_max: default: 32768 minimum: 301
[    0.001548] Mount-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
[    0.001588] Mountpoint-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
[    0.002484] CPU: Testing write buffer coherency: ok
[    0.002522] CPU0: Spectre v2: using BPIALL workaround
[    0.002789] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003686] Setting up static identity map for 0x10100000 - 0x10100060
[    0.003845] rcu: Hierarchical SRCU implementation.
[    0.004844] smp: Bringing up secondary CPUs ...
[    0.005689] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.005698] CPU1: Spectre v2: using BPIALL workaround
[    0.006667] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.006676] CPU2: Spectre v2: using BPIALL workaround
[    0.007606] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.007615] CPU3: Spectre v2: using BPIALL workaround
[    0.007755] smp: Brought up 1 node, 4 CPUs
[    0.007770] SMP: Total of 4 processors activated (24.00 BogoMIPS).
[    0.007780] CPU: All CPU(s) started in SVC mode.
[    0.017479] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
[    0.017696] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.017731] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.017995] pinctrl core: initialized pinctrl subsystem
[    0.019710] NET: Registered protocol family 16
[    0.021665] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.023180] thermal_sys: Registered thermal governor 'step_wise'
[    0.023660] CPU identified as i.MX6Q, silicon rev 1.5
[    0.245571] vdd1p1: supplied by regulator-dummy
[    0.254210] vdd3p0: supplied by regulator-dummy
[    0.262785] vdd2p5: supplied by regulator-dummy
[    0.271321] vddarm: supplied by regulator-dummy
[    0.279909] vddpu: supplied by regulator-dummy
[    0.288419] vddsoc: supplied by regulator-dummy
[    0.628532] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
[    0.628554] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.628861] debugfs: Directory 'dummy-iomuxc-gpr@20e0000' with parent 'regmap' already present!
[    0.629263] imx6q-pinctrl 20e0000.pinctrl: initialized IMX pinctrl driver
[    0.647595] Kprobes globally optimized
[    0.650233] cryptd: max_cpu_qlen set to 1000
[    0.666849] mxs-dma 110000.dma-apbh: initialized
[    0.669973] usb_host_vbus: supplied by usb_host_vbus_hub
[    0.670896] SCSI subsystem initialized
[    0.671303] libata version 3.00 loaded.
[    0.671797] usbcore: registered new interface driver usbfs
[    0.671910] usbcore: registered new interface driver hub
[    0.671999] usbcore: registered new device driver usb
[    0.674185] i2c i2c-0: IMX I2C adapter registered
[    0.676657] i2c i2c-2: IMX I2C adapter registered
[    0.677730] i2c i2c-1: IMX I2C adapter registered
[    0.678202] pps_core: LinuxPPS API ver. 1 registered
[    0.678217] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.678258] PTP clock support registered
[    0.680434] clocksource: Switched to clocksource mxc_timer1
[    0.800167] NET: Registered protocol family 2
[    0.801060] tcp_listen_portaddr_hash hash table entries: 1024 (order: 1, 12288 bytes, linear)
[    0.801141] TCP established hash table entries: 16384 (order: 4, 65536 bytes, linear)
[    0.801432] TCP bind hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    0.802002] TCP: Hash tables configured (established 16384 bind 16384)
[    0.802377] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
[    0.802490] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
[    0.802831] NET: Registered protocol family 1
[    0.802876] PCI: CLS 0 bytes, default 64
[    0.803583] hw perfevents: no interrupt-affinity property for /pmu, guessing.
[    0.803842] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
[    0.809163] workingset: timestamp_bits=14 max_order=19 bucket_order=5
[    0.813910] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.926864] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    0.929303] imx6q-pcie 1ffc000.pcie: host bridge /soc/pcie@1ffc000 ranges:
[    0.929370] imx6q-pcie 1ffc000.pcie:       IO 0x0001f80000..0x0001f8ffff -> 0x0000000000
[    0.929411] imx6q-pcie 1ffc000.pcie:      MEM 0x0001000000..0x0001efffff -> 0x0001000000
[    0.936834] imx-sdma 20ec000.sdma: loaded firmware 3.5
[    0.938840] pfuze100-regulator 2-0008: Full layer: 1, Metal layer: 1
[    0.939545] pfuze100-regulator 2-0008: FAB: 0, FIN: 0
[    0.939560] pfuze100-regulator 2-0008: pfuze100 found.
[    0.956572] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled
[    0.957946] 2020000.serial: ttymxc0 at MMIO 0x2020000 (irq = 34, base_baud = 5000000) is a IMX
[    1.670939] printk: console [ttymxc0] enabled
[    1.676645] 21e8000.serial: ttymxc1 at MMIO 0x21e8000 (irq = 81, base_baud = 5000000) is a IMX
[    1.686125] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 82, base_baud = 5000000) is a IMX
[    1.695541] 21f4000.serial: ttymxc4 at MMIO 0x21f4000 (irq = 83, base_baud = 5000000) is a IMX
[    1.711037] loop: module loaded
[    1.714198] Loading iSCSI transport class v2.0-870.
[    1.720904] ahci-imx 2200000.sata: fsl,transmit-level-mV not specified, using 00000024
[    1.728838] ahci-imx 2200000.sata: fsl,transmit-boost-mdB not specified, using 00000480
[    1.736873] ahci-imx 2200000.sata: fsl,transmit-atten-16ths not specified, using 00002000
[    1.745076] ahci-imx 2200000.sata: fsl,receive-eq-mdB not specified, using 05000000
[    1.752856] ahci-imx 2200000.sata: supply ahci not found, using dummy regulator
[    1.760380] ahci-imx 2200000.sata: supply phy not found, using dummy regulator
[    1.767721] ahci-imx 2200000.sata: supply target not found, using dummy regulator
[    1.778076] ahci-imx 2200000.sata: SSS flag set, parallel bus scan disabled
[    1.785108] ahci-imx 2200000.sata: AHCI 0001.0300 32 slots 1 ports 3 Gbps 0x1 impl platform mode
[    1.793935] ahci-imx 2200000.sata: flags: ncq sntf stag pm led clo only pmp pio slum part ccc apst
[    1.804523] scsi host0: ahci-imx
[    1.808138] ata1: SATA max UDMA/133 mmio [mem 0x02200000-0x02203fff] port 0x100 irq 86
[    1.818261] libphy: Fixed MDIO Bus: probed
[    1.836498] pps pps0: new PPS source ptp0
[    1.842688] libphy: fec_enet_mii_bus: probed
[    1.848952] fec 2188000.ethernet eth0: registered PHC device 0
[    1.855343] e1000e: Intel(R) PRO/1000 Network Driver
[    1.860315] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    1.866373] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.872957] ehci-pci: EHCI PCI platform driver
[    1.877464] ehci-mxc: Freescale On-Chip EHCI Host driver
[    1.886285] rtc-ds1307 0-0068: oscillator failed, set time!
[    1.892036] rtc-ds1307 0-0068: registered as rtc0
[    1.898144] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
[    1.905241] i2c /dev entries driver
[    1.911218] sdhci: Secure Digital Host Controller Interface driver
[    1.917410] sdhci: Copyright(c) Pierre Ossman
[    1.921792] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.928836] sdhci-esdhc-imx 2194000.mmc: Got CD GPIO
[    1.929555] caam 2100000.crypto: Entropy delay = 3200
[    1.966821] mmc2: SDHCI controller on 2198000.mmc [2198000.mmc] using ADMA
[    1.974375] mmc1: SDHCI controller on 2194000.mmc [2194000.mmc] using ADMA
[    1.999674] caam 2100000.crypto: Instantiated RNG4 SH0
[    2.040446] imx6q-pcie 1ffc000.pcie: Phy link never came up
[    2.049259] imx6q-pcie 1ffc000.pcie: PCI host bridge to bus 0000:00
[    2.055566] pci_bus 0000:00: root bus resource [bus 00-ff]
[    2.060434] caam 2100000.crypto: Instantiated RNG4 SH1
[    2.061088] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    2.066207] caam 2100000.crypto: device ID = 0x0a16010000000000 (Era 4)
[    2.072406] pci_bus 0000:00: root bus resource [mem 0x01000000-0x01efffff]
[    2.076096] mmc2: new DDR MMC card at address 0001
[    2.077087] mmcblk2: mmc2:0001 BIWIN  7.28 GiB
[    2.077714] mmcblk2boot0: mmc2:0001 BIWIN  partition 1 4.00 MiB
[    2.078331] mmcblk2boot1: mmc2:0001 BIWIN  partition 2 4.00 MiB
[    2.078464] mmcblk2rpmb: mmc2:0001 BIWIN  partition 3 4.00 MiB, chardev (248:0)
[    2.079029] caam 2100000.crypto: job rings = 2, qi = 0
[    2.079769]  mmcblk2: p1 p2
[    2.085973] pci 0000:00:00.0: [16c3:abcd] type 01 class 0x060400
[    2.098373] caam algorithms registered in /proc/crypto
[    2.101276] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]
[    2.108603] caam 2100000.crypto: registering rng-caam
[    2.114480] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]
[    2.124125] NET: Registered protocol family 10
[    2.128468] pci 0000:00:00.0: Limiting cfg_size to 512
[    2.134736] Segment Routing with IPv6
[    2.139879] pci 0000:00:00.0: imx6_pcie_quirk+0x0/0x84 took 11125 usecs
[    2.142319] ata1: SATA link down (SStatus 0 SControl 300)
[    2.142367] ahci-imx 2200000.sata: no device found, disabling link.
[    2.142376] ahci-imx 2200000.sata: pass ahci_imx..hotplug=1 to enable hotplug
[    2.145016] NET: Registered protocol family 17
[    2.151684] pci 0000:00:00.0: supports D1
[    2.156289] 8021q: 802.1Q VLAN Support v1.8
[    2.161238] pci 0000:00:00.0: PME# supported from D0 D1 D3hot D3cold
[    2.165900] PCI: bus0: Fast back to back transfers disabled
[    2.173156] Registering SWP/SWPB emulation handler
[    2.181426] PCI: bus1: Fast back to back transfers enabled
[    2.185540] Key type ._fscrypt registered
[    2.190445] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-0x010fffff]
[    2.194840] Key type .fscrypt registered
[    2.198843] pci 0000:00:00.0: BAR 6: assigned [mem 0x01100000-0x0110ffff pref]
[    2.203025] Key type fscrypt-provisioning registered
[    2.207714] Key type encrypted registered
[    2.209408] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
[    2.239936] imx_thermal 20c8000.anatop:tempmon: Industrial CPU temperature grade - max:105C critical:100C passive:95C
[    2.240101] pci 0000:00:00.0: Max Payload Size set to  128/ 128 (was  128), Max Read Rq  128
[    2.280656] sysfs: cannot create duplicate filename '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config'
[    2.291471] CPU: 1 PID: 46 Comm: kworker/u8:3 Not tainted 5.10.27 #0
[    2.297832] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[    2.303545] random: fast init done
[    2.304384] Workqueue: events_unbound async_run_entry_fn
[    2.313090] Backtrace:
[    2.315558] [<8010cc88>] (dump_backtrace) from [<8010d134>] (show_stack+0x20/0x24)
[    2.323136]  r7:813285d4 r6:60000013 r5:00000000 r4:80ec845c
[    2.328815] [<8010d114>] (show_stack) from [<805971fc>] (dump_stack+0xa4/0xb8)
[    2.336058] [<80597158>] (dump_stack) from [<803a7128>] (sysfs_warn_dup+0x68/0x74)
[    2.343636]  r7:813285d4 r6:80af0dfc r5:812fc8f0 r4:81bcb000
[    2.349305] [<803a70c0>] (sysfs_warn_dup) from [<803a6c90>] (sysfs_add_file_mode_ns+0x100/0x1cc)
[    2.358098]  r7:813285d4 r6:812fc8f0 r5:80b4299c r4:ffffffef
[    2.363765] [<803a6b90>] (sysfs_add_file_mode_ns) from [<803a6fe8>] (sysfs_create_bin_file+0x94/0x9c)
[    2.372991]  r6:81e68078 r5:80b4299c r4:00000000
[    2.377626] [<803a6f54>] (sysfs_create_bin_file) from [<805da848>] (pci_create_sysfs_dev_files+0x58/0x2cc)
[    2.387285]  r6:81e68000 r5:81e68078 r4:81e68000
[    2.391923] [<805da7f0>] (pci_create_sysfs_dev_files) from [<805cba98>] (pci_bus_add_device+0x34/0x90)
[    2.401237]  r10:80b45d88 r9:81818810 r8:81328400 r7:813285d4 r6:81bd8000 r5:81e68078
[    2.409071]  r4:81e68000
[    2.411615] [<805cba64>] (pci_bus_add_device) from [<805cbb30>] (pci_bus_add_devices+0x3c/0x80)
[    2.420318]  r5:81bd8014 r4:81e68000
[    2.423905] [<805cbaf4>] (pci_bus_add_devices) from [<805cf898>] (pci_host_probe+0x50/0xa0)
[    2.425126] random: crng init done
[    2.432263]  r7:813285d4 r6:81bd8000 r5:81bd800c r4:00000000
[    2.432279] [<805cf848>] (pci_host_probe) from [<805eeb20>] (dw_pcie_host_init+0x1d0/0x414)
[    2.432294]  r7:813285d4 r6:81328258 r5:00000200 r4:00000000
[    2.455360] [<805ee950>] (dw_pcie_host_init) from [<805ef5a8>] (imx6_pcie_probe+0x38c/0x69c)
[    2.463807]  r10:81226180 r9:ef0205c4 r8:81818800 r7:81328240 r6:81328240 r5:81818810
[    2.471640]  r4:00000020
[    2.474197] [<805ef21c>] (imx6_pcie_probe) from [<8065e858>] (platform_drv_probe+0x58/0xa8)
[    2.482557]  r10:80ec9f78 r9:00000000 r8:80f160a8 r7:00000000 r6:80ec9f78 r5:00000000
[    2.490390]  r4:81818810
[    2.492937] [<8065e800>] (platform_drv_probe) from [<8065c0a0>] (really_probe+0x128/0x534)
[    2.501207]  r7:00000000 r6:80f5b8c4 r5:81818810 r4:80f5b8d4
[    2.506877] [<8065bf78>] (really_probe) from [<8065c700>] (driver_probe_device+0x88/0x200)
[    2.515148]  r10:00000000 r9:80f0bb60 r8:00000000 r7:80f160a8 r6:80ec9f78 r5:80ec9f78
[    2.522981]  r4:81818810
[    2.525526] [<8065c678>] (driver_probe_device) from [<8065c904>] (__driver_attach_async_helper+0x8c/0xb4)
[    2.535100]  r9:80f0bb60 r8:00000000 r7:8104d000 r6:80ec9f78 r5:80f25010 r4:81818810
[    2.542853] [<8065c878>] (__driver_attach_async_helper) from [<8015b930>] (async_run_entry_fn+0x58/0x1bc)
[    2.552425]  r6:81a758c0 r5:80f25010 r4:81a758d0
[    2.557060] [<8015b8d8>] (async_run_entry_fn) from [<8015114c>] (process_one_work+0x238/0x5ac)
[    2.565681]  r8:00000000 r7:8104d000 r6:81048400 r5:8127a080 r4:81a758d0
[    2.572392] [<80150f14>] (process_one_work) from [<8015152c>] (worker_thread+0x6c/0x5c0)
[    2.580493]  r10:81048400 r9:80e03d00 r8:81048418 r7:00000088 r6:81048400 r5:8127a094
[    2.588325]  r4:8127a080
[    2.590874] [<801514c0>] (worker_thread) from [<80158168>] (kthread+0x174/0x178)
[    2.598278]  r10:8127a080 r9:81217fe4 r8:8116fe74 r7:81364000 r6:00000000 r5:8127b040
[    2.606111]  r4:81217fc0
[    2.608654] [<80157ff4>] (kthread) from [<80100148>] (ret_from_fork+0x14/0x2c)
[    2.615881] Exception stack(0x81365fb0 to 0x81365ff8)
[    2.620941] 5fa0:                                     00000000 00000000 00000000 00000000
[    2.629127] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[    2.637311] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
[    2.643934]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80157ff4
[    2.651766]  r4:8127b040
[    2.654741] pcieport 0000:00:00.0: PME: Signaling with IRQ 316
[    2.672706] VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
[    2.684075] Freeing unused kernel memory: 1024K
[    2.710947] Run /sbin/init as init process
[    2.715058]   with arguments:
[    2.715065]     /sbin/init
[    2.715073]     earlyprintk
[    2.715079]   with environment:
[    2.715086]     HOME=/
[    2.715092]     TERM=linux
[    2.959976] init: Console is alive
[    2.963628] init: - watchdog -
[    3.364282] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    3.418956] gpio-keys gpio-keys: does not support key code:143
[    3.427977] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    3.441567] init: - preinit -
[    4.224669] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
[    8.560835] EXT4-fs (loop0): recovery complete
[    8.566782] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
[    8.576293] mount_root: switching to ext4 overlay
[    8.824878] EXT4-fs (mmcblk2p1): mounted filesystem without journal. Opts: (null)
[    8.841054] urandom-seed: Seeding with /etc/urandom.seed
[    8.957052] procd: - early -
[    8.960004] procd: - watchdog -
[    9.553020] procd: - watchdog -
[    9.556647] procd: - ubus -
[    9.719723] procd: - init -
[   10.135757] kmodloader: loading kernel modules from /etc/modules.d/*
[   10.147710] urngd: v1.0.2 started.
[   10.158876] can: controller area network core
[   10.163463] NET: Registered protocol family 29
[   10.169546] CAN device driver interface
[   10.174395] can: raw protocol
[   10.510803] sps30 0-0069: failed to reset device
[   10.518325] usbcore: registered new interface driver usbserial_generic
[   10.524997] usbserial: USB Serial support registered for generic
[   10.537468] xt_time: kernel timezone is -0000
[   10.560920] usbcore: registered new interface driver option
[   10.566594] usbserial: USB Serial support registered for GSM modem (1-port)
[   10.580628] kmodloader: done loading kernel modules from /etc/modules.d/*
[   15.264668] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
[   15.280953] br-lan: port 1(eth0) entered blocking state
[   15.286194] br-lan: port 1(eth0) entered disabled state
[   15.291801] device eth0 entered promiscuous mode

Cheers,

Petr

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Koen Vandeputte]

On 07.04.21 17:30, Petr Štetiar wrote:
> Pali Rohár <pali@kernel.org> [2021-04-07 16:51:47]:
>
>> Could you run 'dmesg' and provide its output? So also missing / garbage
>> messages would be visible.
> Adding it inline for archives. It's log from serial console, with output of dmesg at the
> bottom so one can compare if needed.
>
> [    0.000000] Booting Linux on physical CPU 0x0
> [    0.000000] Linux version 5.10.27 (ynezz@ntbk) (arm-openwrt-linux-muslgnueabi-gcc (OpenWrt GCC 8.4.0 r12719+30-84f4a783c698) 8.4.0, GNU ld (GNU Binutils) 2.34) #0 SMP Wed Apr 7 12:52:23 2021
> [    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
> [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> [    0.000000] OF: fdt: Machine model: Toradex Apalis iMX6Q/D Module on Ixora Carrier Board
> [    0.000000] Memory policy: Data cache writealloc
> [    0.000000] Ignoring RAM at 0x80000000-0x90000000
> [    0.000000] Consider using a HIGHMEM enabled kernel.
> [    0.000000] Zone ranges:
> [    0.000000]   Normal   [mem 0x0000000010000000-0x000000007fffffff]
> [    0.000000] Movable zone start for each node
> [    0.000000] Early memory node ranges
> [    0.000000]   node   0: [mem 0x0000000010000000-0x000000007fffffff]
> [    0.000000] Initmem setup node 0 [mem 0x0000000010000000-0x000000007fffffff]
> [    0.000000] percpu: Embedded 19 pages/cpu s47628 r8192 d22004 u77824
> [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 454720
> [    0.000000] Kernel command line: earlyprintk console=ttymxc0,115200n8 root=PARTUUID=5452574f-02 rootfstype=squashfs rootwait pci=nomsi
> [    0.000000] Dentry cache hash table entries: 262144 (order: 8, 1048576 bytes, linear)
> [    0.000000] Inode-cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
> [    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
> [    0.000000] Memory: 1802104K/1835008K available (9040K kernel code, 1170K rwdata, 2328K rodata, 1024K init, 242K bss, 32904K reserved, 0K cma-reserved)
> [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
> [    0.000000] ftrace: allocating 31336 entries in 62 pages
> [    0.000000] ftrace: allocated 62 pages with 5 groups
> [    0.000000] rcu: Hierarchical RCU implementation.
> [    0.000000]  Rude variant of Tasks RCU enabled.
> [    0.000000]  Tracing variant of Tasks RCU enabled.
> [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
> [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
> [    0.000000] L2C-310 errata 752271 769419 enabled
> [    0.000000] L2C-310 enabling early BRESP for Cortex-A9
> [    0.000000] L2C-310 full line of zeros enabled for Cortex-A9
> [    0.000000] L2C-310 ID prefetch enabled, offset 16 lines
> [    0.000000] L2C-310 dynamic clock gating enabled, standby mode enabled
> [    0.000000] L2C-310 cache controller enabled, 16 ways, 1024 kB
> [    0.000000] L2C-310: CACHE_ID 0x410000c7, AUX_CTRL 0x76470001
> [    0.000000] random: get_random_bytes called from start_kernel+0x3e0/0x5a0 with crng_init=0
> [    0.000000] Switching to timer-based delay loop, resolution 333ns
> [    0.000008] sched_clock: 32 bits at 3000kHz, resolution 333ns, wraps every 715827882841ns
> [    0.000029] clocksource: mxc_timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 637086815595 ns
> [    0.001279] Console: colour dummy device 80x30
> [    0.001318] Calibrating delay loop (skipped), value calculated using timer frequency.. 6.00 BogoMIPS (lpj=30000)
> [    0.001340] pid_max: default: 32768 minimum: 301
> [    0.001548] Mount-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
> [    0.001588] Mountpoint-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
> [    0.002484] CPU: Testing write buffer coherency: ok
> [    0.002522] CPU0: Spectre v2: using BPIALL workaround
> [    0.002789] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> [    0.003686] Setting up static identity map for 0x10100000 - 0x10100060
> [    0.003845] rcu: Hierarchical SRCU implementation.
> [    0.004844] smp: Bringing up secondary CPUs ...
> [    0.005689] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
> [    0.005698] CPU1: Spectre v2: using BPIALL workaround
> [    0.006667] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
> [    0.006676] CPU2: Spectre v2: using BPIALL workaround
> [    0.007606] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
> [    0.007615] CPU3: Spectre v2: using BPIALL workaround
> [    0.007755] smp: Brought up 1 node, 4 CPUs
> [    0.007770] SMP: Total of 4 processors activated (24.00 BogoMIPS).
> [    0.007780] CPU: All CPU(s) started in SVC mode.
> [    0.017479] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
> [    0.017696] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
> [    0.017731] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
> [    0.017995] pinctrl core: initialized pinctrl subsystem
> [    0.019710] NET: Registered protocol family 16
> [    0.021665] DMA: preallocated 256 KiB pool for atomic coherent allocations
> [    0.023180] thermal_sys: Registered thermal governor 'step_wise'
> [    0.023660] CPU identified as i.MX6Q, silicon rev 1.5
> [    0.245571] vdd1p1: supplied by regulator-dummy
> [    0.254210] vdd3p0: supplied by regulator-dummy
> [    0.262785] vdd2p5: supplied by regulator-dummy
> [    0.271321] vddarm: supplied by regulator-dummy
> [    0.279909] vddpu: supplied by regulator-dummy
> [    0.288419] vddsoc: supplied by regulator-dummy
> [    0.628532] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
> [    0.628554] hw-breakpoint: maximum watchpoint size is 4 bytes.
> [    0.628861] debugfs: Directory 'dummy-iomuxc-gpr@20e0000' with parent 'regmap' already present!
> [    0.629263] imx6q-pinctrl 20e0000.pinctrl: initialized IMX pinctrl driver
> [    0.647595] Kprobes globally optimized
> [    0.650233] cryptd: max_cpu_qlen set to 1000
> [    0.666849] mxs-dma 110000.dma-apbh: initialized
> [    0.669973] usb_host_vbus: supplied by usb_host_vbus_hub
> [    0.670896] SCSI subsystem initialized
> [    0.671797] usbcore: registered new interface driver usbfs
> [    0.671910] usbcore: registered new interface driver hub
> [    0.671999] usbcore: registered new device driver usb
> [    0.674185] i2c i2c-0: IMX I2C adapter registered
> [    0.676657] i2c i2c-2: IMX I2C adapter registered
> [    0.677730] i2c i2c-1: IMX I2C adapter registered
> [    0.678202] pps_core: LinuxPPS API ver. 1 registered
> [    0.678217] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
> [    0.678258] PTP clock support registered
> [    0.680434] clocksource: Switched to clocksource mxc_timer1
> [    0.800167] NET: Registered protocol family 2
> [    0.801060] tcp_listen_portaddr_hash hash table entries: 1024 (order: 1, 12288 bytes, linear)
> [    0.801141] TCP established hash table entries: 16384 (order: 4, 65536 bytes, linear)
> [    0.801432] TCP bind hash table entries: 16384 (order: 5, 131072 bytes, linear)
> [    0.802002] TCP: Hash tables configured (established 16384 bind 16384)
> [    0.802377] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
> [    0.802490] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
> [    0.802831] NET: Registered protocol family 1
> [    0.802876] PCI: CLS 0 bytes, default 64
> [    0.803583] hw perfevents: no interrupt-affinity property for /pmu, guessing.
> [    0.803842] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
> [    0.809163] workingset: timestamp_bits=14 max_order=19 bucket_order=5
> [    0.813910] squashfs: version 4.0 (2009/01/31) Phillip Lougher
> [    0.926864] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
> [    0.929303] imx6q-pcie 1ffc000.pcie: host bridge /soc/pcie@1ffc000 ranges:
> [    0.929370] imx6q-pcie 1ffc000.pcie:       IO 0x0001f80000..0x0001f8ffff -> 0x0000000000
> [    0.929411] imx6q-pcie 1ffc000.pcie:      MEM 0x0001000000..0x0001efffff -> 0x0001000000
> [    0.936834] imx-sdma 20ec000.sdma: loaded firmware 3.5
> [    0.938840] pfuze100-regulator 2-0008: Full layer: 1, Metal layer: 1
> [    0.939545] pfuze100-regulator 2-0008: FAB: 0, FIN: 0
> [    0.939560] pfuze100-regulator 2-0008: pfuze100 found.
> [    0.956572] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled
> [    0.957946] 2020000.serial: ttymxc0 at MMIO 0x2020000 (irq = 34, base_baud = 5000000) is a IMX
> [    1.670939] printk: console [ttymxc0] enabled
> [    1.676645] 21e8000.serial: ttymxc1 at MMIO 0x21e8000 (irq = 81, base_baud = 5000000) is a IMX
> [    1.686125] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 82, base_baud = 5000000) is a IMX
> [    1.695541] 21f4000.serial: ttymxc4 at MMIO 0x21f4000 (irq = 83, base_baud = 5000000) is a IMX
> [    1.711037] loop: module loaded
> [    1.714198] Loading iSCSI transport class v2.0-870.
> [    1.720904] ahci-imx 2200000.sata: fsl,transmit-level-mV not specified, using 00000024
> [    1.728838] ahci-imx 2200000.sata: fsl,transmit-boost-mdB not specified, using 00000480
> [    1.736873] ahci-imx 2200000.sata: fsl,transmit-atten-16ths not specified, using 00002000
> [    1.745076] ahci-imx 2200000.sata: fsl,receive-eq-mdB not specified, using 05000000
> [    1.752856] ahci-imx 2200000.sata: supply ahci not found, using dummy regulator
> [    1.760380] ahci-imx 2200000.sata: supply phy not found, using dummy regulator
> [    1.767721] ahci-imx 2200000.sata: supply target not found, using dummy regulator
> [    1.778076] ahci-imx 2200000.sata: SSS flag set, parallel bus scan disabled
> [    1.785108] ahci-imx 2200000.sata: AHCI 0001.0300 32 slots 1 ports 3 Gbps 0x1 impl platform mode
> [    1.793935] ahci-imx 2200000.sata: flags: ncq sntf stag pm led clo only pmp pio slum part ccc apst
> [    1.804523] scsi host0: ahci-imx
> [    1.808138] ata1: SATA max UDMA/133 mmio [mem 0x02200000-0x02203fff] port 0x100 irq 86
> [    1.818261] libphy: Fixed MDIO Bus: probed
> [    1.836498] pps pps0: new PPS source ptp0
> [    1.842688] libphy: fec_enet_mii_bus: probed
> [    1.848952] fec 2188000.ethernet eth0: registered PHC device 0
> [    1.855343] e1000e: Intel(R) PRO/1000 Network Driver
> [    1.860315] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
> [    1.866373] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> [    1.872957] ehci-pci: EHCI PCI platform driver
> [    1.877464] ehci-mxc: Freescale On-Chip EHCI Host driver
> [    1.886285] rtc-ds1307 0-0068: oscillator failed, set time!
> [    1.892036] rtc-ds1307 0-0068: registered as rtc0
> [    1.898144] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
> [    1.905241] i2c /dev entries driver
> [    1.911218] sdhci: Secure Digital Host Controller Interface driver
> [    1.917410] sdhci: Copyright(c) Pierre Ossman
> [    1.921792] sdhci-pltfm: SDHCI platform and OF driver helper
> [    1.928836] sdhci-esdhc-imx 2194000.mmc: Got CD GPIO
> [    1.929555] caam 2100000.crypto: Entropy delay = 3200
> [    1.966821] mmc2: SDHCI controller on 2198000.mmc [2198000.mmc] using ADMA
> [    1.974375] mmc1: SDHCI controller on 2194000.mmc [2194000.mmc] using ADMA
> [    1.999674] caam 2100000.crypto: Instantiated RNG4 SH0
> [    2.040446] imx6q-pcie 1ffc000.pcie: Phy link never came up
> [    2.049259] imx6q-pcie 1ffc000.pcie: PCI host bridge to bus 0000:00
> [    2.055566] pci_bus 0000:00: root bus resource [bus 00-ff]
> [    2.060434] caam 2100000.crypto: Instantiated RNG4 SH1
> [    2.061088] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
> [    2.066207] caam 2100000.crypto: device ID = 0x0a16010000000000 (Era 4)
> [    2.072406] pci_bus 0000:00: root bus resource [mem 0x01000000-0x01efffff]
> [    2.076096] mmc2: new DDR MMC card at address 0001
> [    2.077087] mmcblk2: mmc2:0001 BIWIN  7.28 GiB
> [    2.077714] mmcblk2boot0: mmc2:0001 BIWIN  partition 1 4.00 MiB
> [    2.078331] mmcblk2boot1: mmc2:0001 BIWIN  partition 2 4.00 MiB
> [    2.078464] mmcblk2rpmb: mmc2:0001 BIWIN  partition 3 4.00 MiB, chardev (248:0)
> [    2.079029] caam 2100000.crypto: job rings = 2, qi = 0
> [    2.079769]  mmcblk2: p1 p2
> [    2.085973] pci 0000:00:00.0: [16c3:abcd] type 01 class 0x060400
> [    2.098373] caam algorithms registered in /proc/crypto
> [    2.101276] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]
> [    2.108603] caam 2100000.crypto: registering rng-caam
> [    2.114480] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]
> [    2.124125] NET: Registered protocol family 10
> [    2.128468] pci 0000:00:00.0: Limiting cfg_size to 512
> [    2.134736] Segment Routing with IPv6
> [    2.139879] pci 0000:00:00.0: imx6_pcie_quirk+0x0/0x84 took 11125 usecs
> [    2.142319] ata1: SATA link down (SStatus 0 SControl 300)
> [    2.142367] ahci-imx 2200000.sata: no device found, disabling link.
> [    2.142376] ahci-imx 2200000.sata: pass ahci_imx..hotplug=1 to enable hotplug
> [    2.145016] NET: Registered protocol family 17
> [    2.151684] pci 0000:00:00.0: supports D1
> [    2.156289] 8021q: 802.1Q VLAN Support v1.8
> [    2.161238] pci 0000:00:00.0: PME# supported from D0 D1 D3hot D3cold
> [    2.165900] PCI: bus0: Fast back to back transfers disabled
> [    2.173156] Registering SWP/SWPB emulation handler
> [    2.181426] PCI: bus1: Fast back to back transfers enabled
> [    2.185540] Key type ._fscrypt registered
> [    2.190445] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-0x010fffff]
> [    2.194840] Key type .fscrypt registered
> [    2.198843] pci 0000:00:00.0: BAR 6: assigned [mem 0x01100000-0x0110ffff pref]
> [    2.203025] Key type fscrypt-provisioning registered
> [    2.207714] Key type encrypted registered
> [    2.209408] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
> [    2.239936] imx_thermal 20c8000.anatop:tempmon: Industrial CPU temperature grade - max:105C critical:100C passive:95C
> [    2.240101] pci 0000:00:00.0: Max Payload Size set to  128/ 128 (was  128), Max Read Rq  128
> [    2.280656] sysfs: cannot create duplicate filename '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config'
> [    2.291471] CPU: 1 PID: 46 Comm: kworker/u8:3 Not tainted 5.10.27 #0
> [    2.297832] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [    2.303545] random: fast init done
> [    2.304384] Workqueue: events_unbound async_run_entry_fn
> [    2.313090] Backtrace:
> [    2.315558] [<8010cc88>] (dump_backtrace) from [<8010d134>] (show_stack+0x20/0x24)
> [    2.323136]  r7:813285d4 r6:60000013 r5:00000000 r4:80ec845c
> [    2.328815] [<8010d114>] (show_stack) from [<805971fc>] (dump_stack+0xa4/0xb8)
> [    2.336058] [<80597158>] (dump_stack) from [<803a7128>] (sysfs_warn_dup+0x68/0x74)
> [    2.343636]  r7:813285d4 r6:80af0dfc r5:812fc8f0 r4:81bcb000
> [    2.349305] [<803a70c0>] (sysfs_warn_dup) from [<803a6c90>] (sysfs_add_file_mode_ns+0x100/0x1cc)
> [    2.358098]  r7:813285d4 r6:812fc8f0 r5:80b4299c r4:ffffffef
> [    2.363765] [<803a6b90>] (sysfs_add_file_mode_ns) from [<803a6fe8>] (sysfs_create_bin_file+0x94/0x9c)
> [    2.372991]  r6:81e68078 r5:80b4299c r4:00000000
> [    2.377626] [<803a6f54>] (sysfs_create_bin_file) from [<805da848>] (pci_create_sysfs_dev_files+0x58/0x2cc)
> [    2.387285]  r6:81e68000 r5:81e68078 r4:81e68000
> [    2.391923] [<805da7f0>] (pci_create_sysfs_dev_files) from [<805cba98>] (pci_bus_add_device+0x34/0x90)
> [    2.401237]  r10:80b45d88 r9:81818810 r8:81328400 r7:813285d4 r6:81bd8000 r5:81e68078
> [    2.409071]  r4:81e68000
> [    2.411615] [<805cba64>] (pci_bus_add_device) from [<805cbb30>] (pci_bus_add_devices+0x3c/0x80)
> [    2.420318]  r5:81bd8014 r4:81e68000
> [    2.423905] [<805cbaf4>] (pci_bus_add_devices) from [<805cf898>] (pci_host_probe+0x50/0xa0)
> [    2.425126] random: crng init done
> [    2.432263]  r7:813285d4 r6:81bd8000 r5:81bd800c r4:00000000
> [    2.432279] [<805cf848>] (pci_host_probe) from [<805eeb20>] (dw_pcie_host_init+0x1d0/0x414)
> [    2.432294]  r7:813285d4 r6:81328258 r5:00000200 r4:00000000
> [    2.455360] [<805ee950>] (dw_pcie_host_init) from [<805ef5a8>] (imx6_pcie_probe+0x38c/0x69c)
> [    2.463807]  r10:81226180 r9:ef0205c4 r8:81818800 r7:81328240 r6:81328240 r5:81818810
> [    2.471640]  r4:00000020
> [    2.474197] [<805ef21c>] (imx6_pcie_probe) from [<8065e858>] (platform_drv_probe+0x58/0xa8)
> [    2.482557]  r10:80ec9f78 r9:00000000 r8:80f160a8 r7:00000000 r6:80ec9f78 r5:00000000
> [    2.490390]  r4:81818810
> [    2.492937] [<8065e800>] (platform_drv_probe) from [<8065c0a0>] (really_probe+0x128/0x534)
> [    2.501207]  r7:00000000 r6:80f5b8c4 r5:81818810 r4:80f5b8d4
> [    2.506877] [<8065bf78>] (really_probe) from [<8065c700>] (driver_probe_device+0x88/0x200)
> [    2.515148]  r10:00000000 r9:80f0bb60 r8:00000000 r7:80f160a8 r6:80ec9f78 r5:80ec9f78
> [    2.522981]  r4:81818810
> [    2.525526] [<8065c678>] (driver_probe_device) from [<8065c904>] (__driver_attach_async_helper+0x8c/0xb4)
> [    2.535100]  r9:80f0bb60 r8:00000000 r7:8104d000 r6:80ec9f78 r5:80f25010 r4:81818810
> [    2.542853] [<8065c878>] (__driver_attach_async_helper) from [<8015b930>] (async_run_entry_fn+0x58/0x1bc)
> [    2.552425]  r6:81a758c0 r5:80f25010 r4:81a758d0
> [    2.557060] [<8015b8d8>] (async_run_entry_fn) from [<8015114c>] (process_one_work+0x238/0x5ac)
> [    2.565681]  r8:00000000 r7:8104d000 r6:81048400 r5:8127a080 r4:81a758d0
> [    2.572392] [<80150f14>] (process_one_work) from [<8015152c>] (worker_thread+0x6c/0x5c0)
> [    2.580493]  r10:81048400 r9:80e03d00 r8:81048418 r7:00000088 r6:81048400 r5:8127a094
> [    2.588325]  r4:8127a080
> [    2.590874] [<801514c0>] (worker_thread) from [<80158168>] (kthread+0x174/0x178)
> [    2.598278]  r10:8127a080 r9:81217fe4 r8:8116fe74 r7:81364000 r6:00000000 r5:8127b040
> [    2.606111]  r4:81217fc0
> [    2.608654] [<80157ff4>] (kthread) from [<80100148>] (ret_from_fork+0x14/0x2c)
> [    2.615881] Exception stack(0x81365fb0 to 0x81365ff8)
> [    2.620941] 5fa0:                                     00000000 00000000 00000000 00000000
> [    2.629127] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> [    2.637311] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [    2.643934]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80157ff4
> [    2.651766]  r4:8127b040
> [    2.654741] pcieport 0000:00:00.0: PME: Signaling with IRQ 316
> [    2.672706] VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
> [    2.684075] Freeing unused kernel memory: 1024K
> [    2.710947] Run /sbin/init as init process
> [    2.959976] init: Console is alive
> [    2.963628] init: - watchdog -
> [    3.364282] kmodloader: loading kernel modules from /etc/modules-boot.d/*
> [    3.418956] gpio-keys gpio-keys: does not support key code:143
> [    3.427977] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
> [    3.441567] init: - preinit -
> [    4.224669] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
> Press the [f] key and hit [enter] to enter failsafe mode
> Press the [1], [2], [3] or [4] key and hit [enter] to select the debug level
> [    8.560835] EXT4-fs (loop0): recovery complete
> [    8.566782] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
> [    8.576293] mount_root: switching to ext4 overlay
> [    8.824878] EXT4-fs (mmcblk2p1): mounted filesystem without journal. Opts: (null)
> [    8.841054] urandom-seed: Seeding with /etc/urandom.seed
> [    8.957052] procd: - early -
> [    8.960004] procd: - watchdog -
> [    9.553020] procd: - watchdog -
> [    9.556647] procd: - ubus -
> [    9.719723] procd: - init -
> Please press Enter to activate this console.
> [   10.135757] kmodloader: loading kernel modules from /etc/modules.d/*
> [   10.147710] urngd: v1.0.2 started.
> [   10.158876] can: controller area network core
> [   10.163463] NET: Registered protocol family 29
> [   10.169546] CAN device driver interface
> [   10.174395] can: raw protocol
> [   10.510803] sps30 0-0069: failed to reset device
> [   10.518325] usbcore: registered new interface driver usbserial_generic
> [   10.524997] usbserial: USB Serial support registered for generic
> [   10.537468] xt_time: kernel timezone is -0000
> [   10.560920] usbcore: registered new interface driver option
> [   10.566594] usbserial: USB Serial support registered for GSM modem (1-port)
> [   10.580628] kmodloader: done loading kernel modules from /etc/modules.d/*
> [   15.264668] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
> [   15.280953] br-lan: port 1(eth0) entered blocking state
> [   15.286194] br-lan: port 1(eth0) entered disabled state
> [   15.291801] device eth0 entered promiscuous mode
>
>
>
> BusyBox v1.33.0 () built-in shell (ash)
>
>    _______                     ________        __
>   |       |.-----.-----.-----.|  |  |  |.----.|  |_
>   |   -   ||  _  |  -__|     ||  |  |  ||   _||   _|
>   |_______||   __|_____|__|__||________||__|  |____|
>            |__| W I R E L E S S   F R E E D O M
>   -----------------------------------------------------
>   OpenWrt SNAPSHOT, r16433+39-e48c6400e477
>   -----------------------------------------------------
> === WARNING! =====================================
> There is no root password defined on this device!
> Use the "passwd" command to set up a new password
> in order to prevent unauthorized SSH logins.
> --------------------------------------------------
> root@OpenWrt:/# dmesg
> [    0.000000] Booting Linux on physical CPU 0x0
> [    0.000000] Linux version 5.10.27 (ynezz@ntbk) (arm-openwrt-linux-muslgnueabi-gcc (OpenWrt GCC 8.4.0 r12719+30-84f4a783c698) 8.4.0, GNU ld (GNU Binutils) 2.34) #0 SMP Wed Apr 7 12:52:23 2021
> [    0.000000] CPU: ARMv7 Processor [412fc09a] revision 10 (ARMv7), cr=10c5387d
> [    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
> [    0.000000] OF: fdt: Machine model: Toradex Apalis iMX6Q/D Module on Ixora Carrier Board
> [    0.000000] Memory policy: Data cache writealloc
> [    0.000000] Ignoring RAM at 0x80000000-0x90000000
> [    0.000000] Consider using a HIGHMEM enabled kernel.
> [    0.000000] Zone ranges:
> [    0.000000]   Normal   [mem 0x0000000010000000-0x000000007fffffff]
> [    0.000000] Movable zone start for each node
> [    0.000000] Early memory node ranges
> [    0.000000]   node   0: [mem 0x0000000010000000-0x000000007fffffff]
> [    0.000000] Initmem setup node 0 [mem 0x0000000010000000-0x000000007fffffff]
> [    0.000000] On node 0 totalpages: 458752
> [    0.000000]   Normal zone: 4032 pages used for memmap
> [    0.000000]   Normal zone: 0 pages reserved
> [    0.000000]   Normal zone: 458752 pages, LIFO batch:63
> [    0.000000] percpu: Embedded 19 pages/cpu s47628 r8192 d22004 u77824
> [    0.000000] pcpu-alloc: s47628 r8192 d22004 u77824 alloc=19*4096
> [    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
> [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 454720
> [    0.000000] Kernel command line: earlyprintk console=ttymxc0,115200n8 root=PARTUUID=5452574f-02 rootfstype=squashfs rootwait pci=nomsi
> [    0.000000] Dentry cache hash table entries: 262144 (order: 8, 1048576 bytes, linear)
> [    0.000000] Inode-cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
> [    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
> [    0.000000] Memory: 1802104K/1835008K available (9040K kernel code, 1170K rwdata, 2328K rodata, 1024K init, 242K bss, 32904K reserved, 0K cma-reserved)
> [    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
> [    0.000000] ftrace: allocating 31336 entries in 62 pages
> [    0.000000] ftrace: allocated 62 pages with 5 groups
> [    0.000000] rcu: Hierarchical RCU implementation.
> [    0.000000]  Rude variant of Tasks RCU enabled.
> [    0.000000]  Tracing variant of Tasks RCU enabled.
> [    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
> [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
> [    0.000000] L2C-310 errata 752271 769419 enabled
> [    0.000000] L2C-310 enabling early BRESP for Cortex-A9
> [    0.000000] L2C-310 full line of zeros enabled for Cortex-A9
> [    0.000000] L2C-310 ID prefetch enabled, offset 16 lines
> [    0.000000] L2C-310 dynamic clock gating enabled, standby mode enabled
> [    0.000000] L2C-310 cache controller enabled, 16 ways, 1024 kB
> [    0.000000] L2C-310: CACHE_ID 0x410000c7, AUX_CTRL 0x76470001
> [    0.000000] random: get_random_bytes called from start_kernel+0x3e0/0x5a0 with crng_init=0
> [    0.000000] Switching to timer-based delay loop, resolution 333ns
> [    0.000008] sched_clock: 32 bits at 3000kHz, resolution 333ns, wraps every 715827882841ns
> [    0.000029] clocksource: mxc_timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 637086815595 ns
> [    0.001279] Console: colour dummy device 80x30
> [    0.001318] Calibrating delay loop (skipped), value calculated using timer frequency.. 6.00 BogoMIPS (lpj=30000)
> [    0.001340] pid_max: default: 32768 minimum: 301
> [    0.001548] Mount-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
> [    0.001588] Mountpoint-cache hash table entries: 4096 (order: 2, 16384 bytes, linear)
> [    0.002484] CPU: Testing write buffer coherency: ok
> [    0.002522] CPU0: Spectre v2: using BPIALL workaround
> [    0.002789] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
> [    0.003686] Setting up static identity map for 0x10100000 - 0x10100060
> [    0.003845] rcu: Hierarchical SRCU implementation.
> [    0.004844] smp: Bringing up secondary CPUs ...
> [    0.005689] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
> [    0.005698] CPU1: Spectre v2: using BPIALL workaround
> [    0.006667] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
> [    0.006676] CPU2: Spectre v2: using BPIALL workaround
> [    0.007606] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
> [    0.007615] CPU3: Spectre v2: using BPIALL workaround
> [    0.007755] smp: Brought up 1 node, 4 CPUs
> [    0.007770] SMP: Total of 4 processors activated (24.00 BogoMIPS).
> [    0.007780] CPU: All CPU(s) started in SVC mode.
> [    0.017479] VFP support v0.3: implementor 41 architecture 3 part 30 variant 9 rev 4
> [    0.017696] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
> [    0.017731] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
> [    0.017995] pinctrl core: initialized pinctrl subsystem
> [    0.019710] NET: Registered protocol family 16
> [    0.021665] DMA: preallocated 256 KiB pool for atomic coherent allocations
> [    0.023180] thermal_sys: Registered thermal governor 'step_wise'
> [    0.023660] CPU identified as i.MX6Q, silicon rev 1.5
> [    0.245571] vdd1p1: supplied by regulator-dummy
> [    0.254210] vdd3p0: supplied by regulator-dummy
> [    0.262785] vdd2p5: supplied by regulator-dummy
> [    0.271321] vddarm: supplied by regulator-dummy
> [    0.279909] vddpu: supplied by regulator-dummy
> [    0.288419] vddsoc: supplied by regulator-dummy
> [    0.628532] hw-breakpoint: found 5 (+1 reserved) breakpoint and 1 watchpoint registers.
> [    0.628554] hw-breakpoint: maximum watchpoint size is 4 bytes.
> [    0.628861] debugfs: Directory 'dummy-iomuxc-gpr@20e0000' with parent 'regmap' already present!
> [    0.629263] imx6q-pinctrl 20e0000.pinctrl: initialized IMX pinctrl driver
> [    0.647595] Kprobes globally optimized
> [    0.650233] cryptd: max_cpu_qlen set to 1000
> [    0.666849] mxs-dma 110000.dma-apbh: initialized
> [    0.669973] usb_host_vbus: supplied by usb_host_vbus_hub
> [    0.670896] SCSI subsystem initialized
> [    0.671303] libata version 3.00 loaded.
> [    0.671797] usbcore: registered new interface driver usbfs
> [    0.671910] usbcore: registered new interface driver hub
> [    0.671999] usbcore: registered new device driver usb
> [    0.674185] i2c i2c-0: IMX I2C adapter registered
> [    0.676657] i2c i2c-2: IMX I2C adapter registered
> [    0.677730] i2c i2c-1: IMX I2C adapter registered
> [    0.678202] pps_core: LinuxPPS API ver. 1 registered
> [    0.678217] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
> [    0.678258] PTP clock support registered
> [    0.680434] clocksource: Switched to clocksource mxc_timer1
> [    0.800167] NET: Registered protocol family 2
> [    0.801060] tcp_listen_portaddr_hash hash table entries: 1024 (order: 1, 12288 bytes, linear)
> [    0.801141] TCP established hash table entries: 16384 (order: 4, 65536 bytes, linear)
> [    0.801432] TCP bind hash table entries: 16384 (order: 5, 131072 bytes, linear)
> [    0.802002] TCP: Hash tables configured (established 16384 bind 16384)
> [    0.802377] UDP hash table entries: 1024 (order: 3, 32768 bytes, linear)
> [    0.802490] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes, linear)
> [    0.802831] NET: Registered protocol family 1
> [    0.802876] PCI: CLS 0 bytes, default 64
> [    0.803583] hw perfevents: no interrupt-affinity property for /pmu, guessing.
> [    0.803842] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
> [    0.809163] workingset: timestamp_bits=14 max_order=19 bucket_order=5
> [    0.813910] squashfs: version 4.0 (2009/01/31) Phillip Lougher
> [    0.926864] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
> [    0.929303] imx6q-pcie 1ffc000.pcie: host bridge /soc/pcie@1ffc000 ranges:
> [    0.929370] imx6q-pcie 1ffc000.pcie:       IO 0x0001f80000..0x0001f8ffff -> 0x0000000000
> [    0.929411] imx6q-pcie 1ffc000.pcie:      MEM 0x0001000000..0x0001efffff -> 0x0001000000
> [    0.936834] imx-sdma 20ec000.sdma: loaded firmware 3.5
> [    0.938840] pfuze100-regulator 2-0008: Full layer: 1, Metal layer: 1
> [    0.939545] pfuze100-regulator 2-0008: FAB: 0, FIN: 0
> [    0.939560] pfuze100-regulator 2-0008: pfuze100 found.
> [    0.956572] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled
> [    0.957946] 2020000.serial: ttymxc0 at MMIO 0x2020000 (irq = 34, base_baud = 5000000) is a IMX
> [    1.670939] printk: console [ttymxc0] enabled
> [    1.676645] 21e8000.serial: ttymxc1 at MMIO 0x21e8000 (irq = 81, base_baud = 5000000) is a IMX
> [    1.686125] 21f0000.serial: ttymxc3 at MMIO 0x21f0000 (irq = 82, base_baud = 5000000) is a IMX
> [    1.695541] 21f4000.serial: ttymxc4 at MMIO 0x21f4000 (irq = 83, base_baud = 5000000) is a IMX
> [    1.711037] loop: module loaded
> [    1.714198] Loading iSCSI transport class v2.0-870.
> [    1.720904] ahci-imx 2200000.sata: fsl,transmit-level-mV not specified, using 00000024
> [    1.728838] ahci-imx 2200000.sata: fsl,transmit-boost-mdB not specified, using 00000480
> [    1.736873] ahci-imx 2200000.sata: fsl,transmit-atten-16ths not specified, using 00002000
> [    1.745076] ahci-imx 2200000.sata: fsl,receive-eq-mdB not specified, using 05000000
> [    1.752856] ahci-imx 2200000.sata: supply ahci not found, using dummy regulator
> [    1.760380] ahci-imx 2200000.sata: supply phy not found, using dummy regulator
> [    1.767721] ahci-imx 2200000.sata: supply target not found, using dummy regulator
> [    1.778076] ahci-imx 2200000.sata: SSS flag set, parallel bus scan disabled
> [    1.785108] ahci-imx 2200000.sata: AHCI 0001.0300 32 slots 1 ports 3 Gbps 0x1 impl platform mode
> [    1.793935] ahci-imx 2200000.sata: flags: ncq sntf stag pm led clo only pmp pio slum part ccc apst
> [    1.804523] scsi host0: ahci-imx
> [    1.808138] ata1: SATA max UDMA/133 mmio [mem 0x02200000-0x02203fff] port 0x100 irq 86
> [    1.818261] libphy: Fixed MDIO Bus: probed
> [    1.836498] pps pps0: new PPS source ptp0
> [    1.842688] libphy: fec_enet_mii_bus: probed
> [    1.848952] fec 2188000.ethernet eth0: registered PHC device 0
> [    1.855343] e1000e: Intel(R) PRO/1000 Network Driver
> [    1.860315] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
> [    1.866373] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
> [    1.872957] ehci-pci: EHCI PCI platform driver
> [    1.877464] ehci-mxc: Freescale On-Chip EHCI Host driver
> [    1.886285] rtc-ds1307 0-0068: oscillator failed, set time!
> [    1.892036] rtc-ds1307 0-0068: registered as rtc0
> [    1.898144] rtc-ds1307 0-0068: hctosys: unable to read the hardware clock
> [    1.905241] i2c /dev entries driver
> [    1.911218] sdhci: Secure Digital Host Controller Interface driver
> [    1.917410] sdhci: Copyright(c) Pierre Ossman
> [    1.921792] sdhci-pltfm: SDHCI platform and OF driver helper
> [    1.928836] sdhci-esdhc-imx 2194000.mmc: Got CD GPIO
> [    1.929555] caam 2100000.crypto: Entropy delay = 3200
> [    1.966821] mmc2: SDHCI controller on 2198000.mmc [2198000.mmc] using ADMA
> [    1.974375] mmc1: SDHCI controller on 2194000.mmc [2194000.mmc] using ADMA
> [    1.999674] caam 2100000.crypto: Instantiated RNG4 SH0
> [    2.040446] imx6q-pcie 1ffc000.pcie: Phy link never came up
> [    2.049259] imx6q-pcie 1ffc000.pcie: PCI host bridge to bus 0000:00
> [    2.055566] pci_bus 0000:00: root bus resource [bus 00-ff]
> [    2.060434] caam 2100000.crypto: Instantiated RNG4 SH1
> [    2.061088] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
> [    2.066207] caam 2100000.crypto: device ID = 0x0a16010000000000 (Era 4)
> [    2.072406] pci_bus 0000:00: root bus resource [mem 0x01000000-0x01efffff]
> [    2.076096] mmc2: new DDR MMC card at address 0001
> [    2.077087] mmcblk2: mmc2:0001 BIWIN  7.28 GiB
> [    2.077714] mmcblk2boot0: mmc2:0001 BIWIN  partition 1 4.00 MiB
> [    2.078331] mmcblk2boot1: mmc2:0001 BIWIN  partition 2 4.00 MiB
> [    2.078464] mmcblk2rpmb: mmc2:0001 BIWIN  partition 3 4.00 MiB, chardev (248:0)
> [    2.079029] caam 2100000.crypto: job rings = 2, qi = 0
> [    2.079769]  mmcblk2: p1 p2
> [    2.085973] pci 0000:00:00.0: [16c3:abcd] type 01 class 0x060400
> [    2.098373] caam algorithms registered in /proc/crypto
> [    2.101276] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x000fffff]
> [    2.108603] caam 2100000.crypto: registering rng-caam
> [    2.114480] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]
> [    2.124125] NET: Registered protocol family 10
> [    2.128468] pci 0000:00:00.0: Limiting cfg_size to 512
> [    2.134736] Segment Routing with IPv6
> [    2.139879] pci 0000:00:00.0: imx6_pcie_quirk+0x0/0x84 took 11125 usecs
> [    2.142319] ata1: SATA link down (SStatus 0 SControl 300)
> [    2.142367] ahci-imx 2200000.sata: no device found, disabling link.
> [    2.142376] ahci-imx 2200000.sata: pass ahci_imx..hotplug=1 to enable hotplug
> [    2.145016] NET: Registered protocol family 17
> [    2.151684] pci 0000:00:00.0: supports D1
> [    2.156289] 8021q: 802.1Q VLAN Support v1.8
> [    2.161238] pci 0000:00:00.0: PME# supported from D0 D1 D3hot D3cold
> [    2.165900] PCI: bus0: Fast back to back transfers disabled
> [    2.173156] Registering SWP/SWPB emulation handler
> [    2.181426] PCI: bus1: Fast back to back transfers enabled
> [    2.185540] Key type ._fscrypt registered
> [    2.190445] pci 0000:00:00.0: BAR 0: assigned [mem 0x01000000-0x010fffff]
> [    2.194840] Key type .fscrypt registered
> [    2.198843] pci 0000:00:00.0: BAR 6: assigned [mem 0x01100000-0x0110ffff pref]
> [    2.203025] Key type fscrypt-provisioning registered
> [    2.207714] Key type encrypted registered
> [    2.209408] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
> [    2.239936] imx_thermal 20c8000.anatop:tempmon: Industrial CPU temperature grade - max:105C critical:100C passive:95C
> [    2.240101] pci 0000:00:00.0: Max Payload Size set to  128/ 128 (was  128), Max Read Rq  128
> [    2.280656] sysfs: cannot create duplicate filename '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config'
> [    2.291471] CPU: 1 PID: 46 Comm: kworker/u8:3 Not tainted 5.10.27 #0
> [    2.297832] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [    2.303545] random: fast init done
> [    2.304384] Workqueue: events_unbound async_run_entry_fn
> [    2.313090] Backtrace:
> [    2.315558] [<8010cc88>] (dump_backtrace) from [<8010d134>] (show_stack+0x20/0x24)
> [    2.323136]  r7:813285d4 r6:60000013 r5:00000000 r4:80ec845c
> [    2.328815] [<8010d114>] (show_stack) from [<805971fc>] (dump_stack+0xa4/0xb8)
> [    2.336058] [<80597158>] (dump_stack) from [<803a7128>] (sysfs_warn_dup+0x68/0x74)
> [    2.343636]  r7:813285d4 r6:80af0dfc r5:812fc8f0 r4:81bcb000
> [    2.349305] [<803a70c0>] (sysfs_warn_dup) from [<803a6c90>] (sysfs_add_file_mode_ns+0x100/0x1cc)
> [    2.358098]  r7:813285d4 r6:812fc8f0 r5:80b4299c r4:ffffffef
> [    2.363765] [<803a6b90>] (sysfs_add_file_mode_ns) from [<803a6fe8>] (sysfs_create_bin_file+0x94/0x9c)
> [    2.372991]  r6:81e68078 r5:80b4299c r4:00000000
> [    2.377626] [<803a6f54>] (sysfs_create_bin_file) from [<805da848>] (pci_create_sysfs_dev_files+0x58/0x2cc)
> [    2.387285]  r6:81e68000 r5:81e68078 r4:81e68000
> [    2.391923] [<805da7f0>] (pci_create_sysfs_dev_files) from [<805cba98>] (pci_bus_add_device+0x34/0x90)
> [    2.401237]  r10:80b45d88 r9:81818810 r8:81328400 r7:813285d4 r6:81bd8000 r5:81e68078
> [    2.409071]  r4:81e68000
> [    2.411615] [<805cba64>] (pci_bus_add_device) from [<805cbb30>] (pci_bus_add_devices+0x3c/0x80)
> [    2.420318]  r5:81bd8014 r4:81e68000
> [    2.423905] [<805cbaf4>] (pci_bus_add_devices) from [<805cf898>] (pci_host_probe+0x50/0xa0)
> [    2.425126] random: crng init done
> [    2.432263]  r7:813285d4 r6:81bd8000 r5:81bd800c r4:00000000
> [    2.432279] [<805cf848>] (pci_host_probe) from [<805eeb20>] (dw_pcie_host_init+0x1d0/0x414)
> [    2.432294]  r7:813285d4 r6:81328258 r5:00000200 r4:00000000
> [    2.455360] [<805ee950>] (dw_pcie_host_init) from [<805ef5a8>] (imx6_pcie_probe+0x38c/0x69c)
> [    2.463807]  r10:81226180 r9:ef0205c4 r8:81818800 r7:81328240 r6:81328240 r5:81818810
> [    2.471640]  r4:00000020
> [    2.474197] [<805ef21c>] (imx6_pcie_probe) from [<8065e858>] (platform_drv_probe+0x58/0xa8)
> [    2.482557]  r10:80ec9f78 r9:00000000 r8:80f160a8 r7:00000000 r6:80ec9f78 r5:00000000
> [    2.490390]  r4:81818810
> [    2.492937] [<8065e800>] (platform_drv_probe) from [<8065c0a0>] (really_probe+0x128/0x534)
> [    2.501207]  r7:00000000 r6:80f5b8c4 r5:81818810 r4:80f5b8d4
> [    2.506877] [<8065bf78>] (really_probe) from [<8065c700>] (driver_probe_device+0x88/0x200)
> [    2.515148]  r10:00000000 r9:80f0bb60 r8:00000000 r7:80f160a8 r6:80ec9f78 r5:80ec9f78
> [    2.522981]  r4:81818810
> [    2.525526] [<8065c678>] (driver_probe_device) from [<8065c904>] (__driver_attach_async_helper+0x8c/0xb4)
> [    2.535100]  r9:80f0bb60 r8:00000000 r7:8104d000 r6:80ec9f78 r5:80f25010 r4:81818810
> [    2.542853] [<8065c878>] (__driver_attach_async_helper) from [<8015b930>] (async_run_entry_fn+0x58/0x1bc)
> [    2.552425]  r6:81a758c0 r5:80f25010 r4:81a758d0
> [    2.557060] [<8015b8d8>] (async_run_entry_fn) from [<8015114c>] (process_one_work+0x238/0x5ac)
> [    2.565681]  r8:00000000 r7:8104d000 r6:81048400 r5:8127a080 r4:81a758d0
> [    2.572392] [<80150f14>] (process_one_work) from [<8015152c>] (worker_thread+0x6c/0x5c0)
> [    2.580493]  r10:81048400 r9:80e03d00 r8:81048418 r7:00000088 r6:81048400 r5:8127a094
> [    2.588325]  r4:8127a080
> [    2.590874] [<801514c0>] (worker_thread) from [<80158168>] (kthread+0x174/0x178)
> [    2.598278]  r10:8127a080 r9:81217fe4 r8:8116fe74 r7:81364000 r6:00000000 r5:8127b040
> [    2.606111]  r4:81217fc0
> [    2.608654] [<80157ff4>] (kthread) from [<80100148>] (ret_from_fork+0x14/0x2c)
> [    2.615881] Exception stack(0x81365fb0 to 0x81365ff8)
> [    2.620941] 5fa0:                                     00000000 00000000 00000000 00000000
> [    2.629127] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
> [    2.637311] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> [    2.643934]  r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:80157ff4
> [    2.651766]  r4:8127b040
> [    2.654741] pcieport 0000:00:00.0: PME: Signaling with IRQ 316
> [    2.672706] VFS: Mounted root (squashfs filesystem) readonly on device 179:2.
> [    2.684075] Freeing unused kernel memory: 1024K
> [    2.710947] Run /sbin/init as init process
> [    2.715058]   with arguments:
> [    2.715065]     /sbin/init
> [    2.715073]     earlyprintk
> [    2.715079]   with environment:
> [    2.715086]     HOME=/
> [    2.715092]     TERM=linux
> [    2.959976] init: Console is alive
> [    2.963628] init: - watchdog -
> [    3.364282] kmodloader: loading kernel modules from /etc/modules-boot.d/*
> [    3.418956] gpio-keys gpio-keys: does not support key code:143
> [    3.427977] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
> [    3.441567] init: - preinit -
> [    4.224669] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
> [    8.560835] EXT4-fs (loop0): recovery complete
> [    8.566782] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null)
> [    8.576293] mount_root: switching to ext4 overlay
> [    8.824878] EXT4-fs (mmcblk2p1): mounted filesystem without journal. Opts: (null)
> [    8.841054] urandom-seed: Seeding with /etc/urandom.seed
> [    8.957052] procd: - early -
> [    8.960004] procd: - watchdog -
> [    9.553020] procd: - watchdog -
> [    9.556647] procd: - ubus -
> [    9.719723] procd: - init -
> [   10.135757] kmodloader: loading kernel modules from /etc/modules.d/*
> [   10.147710] urngd: v1.0.2 started.
> [   10.158876] can: controller area network core
> [   10.163463] NET: Registered protocol family 29
> [   10.169546] CAN device driver interface
> [   10.174395] can: raw protocol
> [   10.510803] sps30 0-0069: failed to reset device
> [   10.518325] usbcore: registered new interface driver usbserial_generic
> [   10.524997] usbserial: USB Serial support registered for generic
> [   10.537468] xt_time: kernel timezone is -0000
> [   10.560920] usbcore: registered new interface driver option
> [   10.566594] usbserial: USB Serial support registered for GSM modem (1-port)
> [   10.580628] kmodloader: done loading kernel modules from /etc/modules.d/*
> [   15.264668] Micrel KSZ9031 Gigabit PHY 2188000.ethernet-1:07: attached PHY driver [Micrel KSZ9031 Gigabit PHY] (mii_bus:phy_addr=2188000.ethernet-1:07, irq=120)
> [   15.280953] br-lan: port 1(eth0) entered blocking state
> [   15.286194] br-lan: port 1(eth0) entered disabled state
> [   15.291801] device eth0 entered promiscuous mode
>
> Cheers,
>
> Petr

Hi all,


Adding some more info regarding this issue:

I've cooked up this simple patch to get some more info:


Index: linux-5.10.44/drivers/pci/pci-sysfs.c
===================================================================
--- linux-5.10.44.orig/drivers/pci/pci-sysfs.c
+++ linux-5.10.44/drivers/pci/pci-sysfs.c
@@ -1335,6 +1335,8 @@ int __must_check pci_create_sysfs_dev_fi
      int rom_size;
      struct bin_attribute *attr;

+    dump_stack();
+
      if (!sysfs_initialized)
          return -EACCES;


Which shows this:


[    1.847384] Key type .fscrypt registered
[    1.854288] pci 0000:01:00.0: PCI bridge to [bus 02-05]
[    1.859242] Key type fscrypt-provisioning registered
[    1.863252] pci 0000:01:00.0:   bridge window [mem 0x01100000-0x011fffff]
[    1.874096] Key type encrypted registered
[    1.879290] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
[    1.879306] pci 0000:00:00.0:   bridge window [mem 0x01100000-0x012fffff]

--> patch kicking in here showing first creation now

[    1.879346] CPU: 1 PID: 7 Comm: kworker/u4:0 Not tainted 5.10.44 #0
[    1.913354] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[    1.919908] Workqueue: events_unbound async_run_entry_fn
[    1.925255] [<8010d5e0>] (unwind_backtrace) from [<801099f0>] 
(show_stack+0x10/0x14)
[    1.933008] [<801099f0>] (show_stack) from [<804ab92c>] 
(dump_stack+0x94/0xa8)
[    1.940249] [<804ab92c>] (dump_stack) from [<804ea96c>] 
(pci_create_sysfs_dev_files+0x10/0x28c)
[    1.948969] [<804ea96c>] (pci_create_sysfs_dev_files) from 
[<804dc648>] (pci_bus_add_device+0x20/0x84)
[    1.958287] [<804dc648>] (pci_bus_add_device) from [<804dc6d8>] 
(pci_bus_add_devices+0x2c/0x70)
[    1.966996] [<804dc6d8>] (pci_bus_add_devices) from [<804dffc8>] 
(pci_host_probe+0x40/0x94)
[    1.975362] [<804dffc8>] (pci_host_probe) from [<804fd5f0>] 
(dw_pcie_host_init+0x1c0/0x3fc)
[    1.983720] [<804fd5f0>] (dw_pcie_host_init) from [<804fdcb0>] 
(imx6_pcie_probe+0x358/0x63c)
[    1.992179] [<804fdcb0>] (imx6_pcie_probe) from [<8054c79c>] 
(platform_drv_probe+0x48/0x98)
[    2.000542] [<8054c79c>] (platform_drv_probe) from [<8054a9fc>] 
(really_probe+0xfc/0x4dc)
[    2.008732] [<8054a9fc>] (really_probe) from [<8054b0bc>] 
(driver_probe_device+0x5c/0xb4)
[    2.016916] [<8054b0bc>] (driver_probe_device) from [<8054b1bc>] 
(__driver_attach_async_helper+0xa8/0xac)
[    2.026497] [<8054b1bc>] (__driver_attach_async_helper) from 
[<8014beec>] (async_run_entry_fn+0x44/0x108)
[    2.036082] [<8014beec>] (async_run_entry_fn) from [<80141b64>] 
(process_one_work+0x1d8/0x43c)
[    2.044704] [<80141b64>] (process_one_work) from [<80141e2c>] 
(worker_thread+0x64/0x5b0)
[    2.052802] [<80141e2c>] (worker_thread) from [<80147698>] 
(kthread+0x148/0x14c)
[    2.060207] [<80147698>] (kthread) from [<80100148>] 
(ret_from_fork+0x14/0x2c)
[    2.067433] Exception stack(0x81075fb0 to 0x81075ff8)
[    2.072493] 5fa0:                                     00000000 
00000000 00000000 00000000
[    2.080678] 5fc0: 00000000 00000000 00000000 00000000 00000000 
00000000 00000000 00000000
[    2.088864] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000

--> getting called again ..  different caller this time .. seems 
unimportant ?

[    2.095490] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.10.44 #0
[    2.095924] pcieport 0000:00:00.0: PME: Signaling with IRQ 307
[    2.101510] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[    2.113883] [<8010d5e0>] (unwind_backtrace) from [<801099f0>] 
(show_stack+0x10/0x14)
[    2.121638] [<801099f0>] (show_stack) from [<804ab92c>] 
(dump_stack+0x94/0xa8)
[    2.128875] [<804ab92c>] (dump_stack) from [<804ea96c>] 
(pci_create_sysfs_dev_files+0x10/0x28c)
[    2.137588] [<804ea96c>] (pci_create_sysfs_dev_files) from 
[<80b1b920>] (pci_sysfs_init+0x34/0x54)
[    2.146559] [<80b1b920>] (pci_sysfs_init) from [<80101820>] 
(do_one_initcall+0x54/0x1e8)
[    2.154667] [<80101820>] (do_one_initcall) from [<80b01108>] 
(kernel_init_freeable+0x23c/0x290)
[    2.163386] [<80b01108>] (kernel_init_freeable) from [<80837e3c>] 
(kernel_init+0x8/0x118)
[    2.171578] [<80837e3c>] (kernel_init) from [<80100148>] 
(ret_from_fork+0x14/0x2c)
[    2.179151] Exception stack(0x81053fb0 to 0x81053ff8)
[    2.184210] 3fa0:                                     00000000 
00000000 00000000 00000000
[    2.192393] 3fc0: 00000000 00000000 00000000 00000000 00000000 
00000000 00000000 00000000
[    2.200575] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000

--> And then finally, the error occurs as it's already been added 
before.  same cpu and same PID trying to add the same stuff again to sysfs

[    2.207200] CPU: 1 PID: 7 Comm: kworker/u4:0 Not tainted 5.10.44 #0
[    2.207263] sysfs: cannot create duplicate filename 
'/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config' <------
[    2.213478] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
[    2.230798] Workqueue: events_unbound async_run_entry_fn
[    2.236129] [<8010d5e0>] (unwind_backtrace) from [<801099f0>] 
(show_stack+0x10/0x14)
[    2.243882] [<801099f0>] (show_stack) from [<804ab92c>] 
(dump_stack+0x94/0xa8)
[    2.251118] [<804ab92c>] (dump_stack) from [<804ea96c>] 
(pci_create_sysfs_dev_files+0x10/0x28c)
[    2.259837] [<804ea96c>] (pci_create_sysfs_dev_files) from 
[<804dc648>] (pci_bus_add_device+0x20/0x84)
[    2.269153] [<804dc648>] (pci_bus_add_device) from [<804dc6d8>] 
(pci_bus_add_devices+0x2c/0x70)
[    2.277861] [<804dc6d8>] (pci_bus_add_devices) from [<804dc70c>] 
(pci_bus_add_devices+0x60/0x70)
[    2.286656] [<804dc70c>] (pci_bus_add_devices) from [<804dffc8>] 
(pci_host_probe+0x40/0x94)
[    2.295018] [<804dffc8>] (pci_host_probe) from [<804fd5f0>] 
(dw_pcie_host_init+0x1c0/0x3fc)
[    2.303377] [<804fd5f0>] (dw_pcie_host_init) from [<804fdcb0>] 
(imx6_pcie_probe+0x358/0x63c)
[    2.311832] [<804fdcb0>] (imx6_pcie_probe) from [<8054c79c>] 
(platform_drv_probe+0x48/0x98)
[    2.320196] [<8054c79c>] (platform_drv_probe) from [<8054a9fc>] 
(really_probe+0xfc/0x4dc)
[    2.328382] [<8054a9fc>] (really_probe) from [<8054b0bc>] 
(driver_probe_device+0x5c/0xb4)
[    2.336567] [<8054b0bc>] (driver_probe_device) from [<8054b1bc>] 
(__driver_attach_async_helper+0xa8/0xac)
[    2.346145] [<8054b1bc>] (__driver_attach_async_helper) from 
[<8014beec>] (async_run_entry_fn+0x44/0x108)
[    2.355727] [<8014beec>] (async_run_entry_fn) from [<80141b64>] 
(process_one_work+0x1d8/0x43c)
[    2.364350] [<80141b64>] (process_one_work) from [<80141e2c>] 
(worker_thread+0x64/0x5b0)
[    2.372449] [<80141e2c>] (worker_thread) from [<80147698>] 
(kthread+0x148/0x14c)
[    2.379853] [<80147698>] (kthread) from [<80100148>] 
(ret_from_fork+0x14/0x2c)
[    2.387077] Exception stack(0x81075fb0 to 0x81075ff8)
[    2.392134] 5fa0:                                     00000000 
00000000 00000000 00000000
[    2.400317] 5fc0: 00000000 00000000 00000000 00000000 00000000 
00000000 00000000 00000000
[    2.408498] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000



Any idea?

Thanks,

Koen

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Pali Rohár]

Hello!

On Friday 25 June 2021 13:29:00 Koen Vandeputte wrote:
> Hi all,
> 
> 
> Adding some more info regarding this issue:
> 
> I've cooked up this simple patch to get some more info:
> 
> 
> Index: linux-5.10.44/drivers/pci/pci-sysfs.c
> ===================================================================
> --- linux-5.10.44.orig/drivers/pci/pci-sysfs.c
> +++ linux-5.10.44/drivers/pci/pci-sysfs.c
> @@ -1335,6 +1335,8 @@ int __must_check pci_create_sysfs_dev_fi
>      int rom_size;
>      struct bin_attribute *attr;
> 
> +    dump_stack();
> +
>      if (!sysfs_initialized)
>          return -EACCES;
> 
> 
> Which shows this:
> 
> 
> [    1.847384] Key type .fscrypt registered
> [    1.854288] pci 0000:01:00.0: PCI bridge to [bus 02-05]
> [    1.859242] Key type fscrypt-provisioning registered
> [    1.863252] pci 0000:01:00.0:   bridge window [mem 0x01100000-0x011fffff]
> [    1.874096] Key type encrypted registered
> [    1.879290] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
> [    1.879306] pci 0000:00:00.0:   bridge window [mem 0x01100000-0x012fffff]
> 
> --> patch kicking in here showing first creation now
> 
> [    1.879346] CPU: 1 PID: 7 Comm: kworker/u4:0 Not tainted 5.10.44 #0
> [    1.913354] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [    1.919908] Workqueue: events_unbound async_run_entry_fn
> [    1.925255] [<8010d5e0>] (unwind_backtrace) from [<801099f0>]
> (show_stack+0x10/0x14)
> [    1.933008] [<801099f0>] (show_stack) from [<804ab92c>]
> (dump_stack+0x94/0xa8)
> [    1.940249] [<804ab92c>] (dump_stack) from [<804ea96c>]
> (pci_create_sysfs_dev_files+0x10/0x28c)
> [    1.948969] [<804ea96c>] (pci_create_sysfs_dev_files) from [<804dc648>]
> (pci_bus_add_device+0x20/0x84)
> [    1.958287] [<804dc648>] (pci_bus_add_device) from [<804dc6d8>]
> (pci_bus_add_devices+0x2c/0x70)
> [    1.966996] [<804dc6d8>] (pci_bus_add_devices) from [<804dffc8>]
> (pci_host_probe+0x40/0x94)
> [    1.975362] [<804dffc8>] (pci_host_probe) from [<804fd5f0>]
> (dw_pcie_host_init+0x1c0/0x3fc)
> [    1.983720] [<804fd5f0>] (dw_pcie_host_init) from [<804fdcb0>]
> (imx6_pcie_probe+0x358/0x63c)
> [    1.992179] [<804fdcb0>] (imx6_pcie_probe) from [<8054c79c>]
> (platform_drv_probe+0x48/0x98)
> [    2.000542] [<8054c79c>] (platform_drv_probe) from [<8054a9fc>]
> (really_probe+0xfc/0x4dc)
> [    2.008732] [<8054a9fc>] (really_probe) from [<8054b0bc>]
> (driver_probe_device+0x5c/0xb4)
> [    2.016916] [<8054b0bc>] (driver_probe_device) from [<8054b1bc>]
> (__driver_attach_async_helper+0xa8/0xac)
> [    2.026497] [<8054b1bc>] (__driver_attach_async_helper) from [<8014beec>]
> (async_run_entry_fn+0x44/0x108)
> [    2.036082] [<8014beec>] (async_run_entry_fn) from [<80141b64>]
> (process_one_work+0x1d8/0x43c)
> [    2.044704] [<80141b64>] (process_one_work) from [<80141e2c>]
> (worker_thread+0x64/0x5b0)
> [    2.052802] [<80141e2c>] (worker_thread) from [<80147698>]
> (kthread+0x148/0x14c)
> [    2.060207] [<80147698>] (kthread) from [<80100148>]
> (ret_from_fork+0x14/0x2c)
> [    2.067433] Exception stack(0x81075fb0 to 0x81075ff8)
> [    2.072493] 5fa0:                                     00000000 00000000
> 00000000 00000000
> [    2.080678] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000
> [    2.088864] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> 
> --> getting called again ..  different caller this time .. seems unimportant
> ?
> 
> [    2.095490] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.10.44 #0
> [    2.095924] pcieport 0000:00:00.0: PME: Signaling with IRQ 307
> [    2.101510] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [    2.113883] [<8010d5e0>] (unwind_backtrace) from [<801099f0>]
> (show_stack+0x10/0x14)
> [    2.121638] [<801099f0>] (show_stack) from [<804ab92c>]
> (dump_stack+0x94/0xa8)
> [    2.128875] [<804ab92c>] (dump_stack) from [<804ea96c>]
> (pci_create_sysfs_dev_files+0x10/0x28c)
> [    2.137588] [<804ea96c>] (pci_create_sysfs_dev_files) from [<80b1b920>]
> (pci_sysfs_init+0x34/0x54)
> [    2.146559] [<80b1b920>] (pci_sysfs_init) from [<80101820>]
> (do_one_initcall+0x54/0x1e8)
> [    2.154667] [<80101820>] (do_one_initcall) from [<80b01108>]
> (kernel_init_freeable+0x23c/0x290)
> [    2.163386] [<80b01108>] (kernel_init_freeable) from [<80837e3c>]
> (kernel_init+0x8/0x118)
> [    2.171578] [<80837e3c>] (kernel_init) from [<80100148>]
> (ret_from_fork+0x14/0x2c)
> [    2.179151] Exception stack(0x81053fb0 to 0x81053ff8)
> [    2.184210] 3fa0:                                     00000000 00000000
> 00000000 00000000
> [    2.192393] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000
> [    2.200575] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> 
> --> And then finally, the error occurs as it's already been added before. 
> same cpu and same PID trying to add the same stuff again to sysfs

This just proves that you have hit this race condition.

> [    2.207200] CPU: 1 PID: 7 Comm: kworker/u4:0 Not tainted 5.10.44 #0
> [    2.207263] sysfs: cannot create duplicate filename
> '/devices/platform/soc/1ffc000.pcie/pci0000:00/0000:00:00.0/config' <------
> [    2.213478] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree)
> [    2.230798] Workqueue: events_unbound async_run_entry_fn
> [    2.236129] [<8010d5e0>] (unwind_backtrace) from [<801099f0>]
> (show_stack+0x10/0x14)
> [    2.243882] [<801099f0>] (show_stack) from [<804ab92c>]
> (dump_stack+0x94/0xa8)
> [    2.251118] [<804ab92c>] (dump_stack) from [<804ea96c>]
> (pci_create_sysfs_dev_files+0x10/0x28c)
> [    2.259837] [<804ea96c>] (pci_create_sysfs_dev_files) from [<804dc648>]
> (pci_bus_add_device+0x20/0x84)
> [    2.269153] [<804dc648>] (pci_bus_add_device) from [<804dc6d8>]
> (pci_bus_add_devices+0x2c/0x70)
> [    2.277861] [<804dc6d8>] (pci_bus_add_devices) from [<804dc70c>]
> (pci_bus_add_devices+0x60/0x70)
> [    2.286656] [<804dc70c>] (pci_bus_add_devices) from [<804dffc8>]
> (pci_host_probe+0x40/0x94)
> [    2.295018] [<804dffc8>] (pci_host_probe) from [<804fd5f0>]
> (dw_pcie_host_init+0x1c0/0x3fc)
> [    2.303377] [<804fd5f0>] (dw_pcie_host_init) from [<804fdcb0>]
> (imx6_pcie_probe+0x358/0x63c)
> [    2.311832] [<804fdcb0>] (imx6_pcie_probe) from [<8054c79c>]
> (platform_drv_probe+0x48/0x98)
> [    2.320196] [<8054c79c>] (platform_drv_probe) from [<8054a9fc>]
> (really_probe+0xfc/0x4dc)
> [    2.328382] [<8054a9fc>] (really_probe) from [<8054b0bc>]
> (driver_probe_device+0x5c/0xb4)
> [    2.336567] [<8054b0bc>] (driver_probe_device) from [<8054b1bc>]
> (__driver_attach_async_helper+0xa8/0xac)
> [    2.346145] [<8054b1bc>] (__driver_attach_async_helper) from [<8014beec>]
> (async_run_entry_fn+0x44/0x108)
> [    2.355727] [<8014beec>] (async_run_entry_fn) from [<80141b64>]
> (process_one_work+0x1d8/0x43c)
> [    2.364350] [<80141b64>] (process_one_work) from [<80141e2c>]
> (worker_thread+0x64/0x5b0)
> [    2.372449] [<80141e2c>] (worker_thread) from [<80147698>]
> (kthread+0x148/0x14c)
> [    2.379853] [<80147698>] (kthread) from [<80100148>]
> (ret_from_fork+0x14/0x2c)
> [    2.387077] Exception stack(0x81075fb0 to 0x81075ff8)
> [    2.392134] 5fa0:                                     00000000 00000000
> 00000000 00000000
> [    2.400317] 5fc0: 00000000 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000
> [    2.408498] 5fe0: 00000000 00000000 00000000 00000000 00000013 00000000
> 
> 
> 
> Any idea?
> 
> Thanks,
> 
> Koen
> 

It is same race condition which I described in the first email of this
email thread. I described exactly when it happens. I'm not able to
trigger it with new kernels but as we know race conditions are hard to
trigger...

So result is that we know about it, just fix is not ready yet as it is
not easy to fix it.

Krzysztof has been working on fixing it, so maybe can provide an
update...

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Dexuan-Linux Cui]

On Fri, Jun 25, 2021 at 4:55 AM Pali Rohár <pali@kernel.org> wrote:
>
> Hello!
>
> On Friday 25 June 2021 13:29:00 Koen Vandeputte wrote:
> > ...
> It is same race condition which I described in the first email of this
> email thread. I described exactly when it happens. I'm not able to
> trigger it with new kernels but as we know race conditions are hard to
> trigger...
>
> So result is that we know about it, just fix is not ready yet as it is
> not easy to fix it.
>
> Krzysztof has been working on fixing it, so maybe can provide an
> update...

I think we're seeing the same issue with a Linux VM on Hyper-V. Here
the kernel is https://git.launchpad.net/~canonical-kernel/ubuntu/+source/linux-azure/+git/bionic/tree/?h=Ubuntu-azure-5.4-5.4.0-1061.64_18.04.1

[    4.680707] hv_pci 47505500-0003-0000-3130-444531334632: PCI VMBus
probing: Using version 0x10002
[    4.730457] hv_pci 47505500-0003-0000-3130-444531334632: PCI host
bridge to bus 0003:00
[    4.735577] pci_bus 0003:00: root bus resource [mem
0x43000000-0x43ffffff window]
[    4.742189] pci_bus 0003:00: root bus resource [mem
0x1020000000-0x1031ffffff window]
[    4.747027] pci 0003:00:00.0: [10de:13f2] type 00 class 0x030000
[    4.770114] pci 0003:00:00.0: reg 0x10: [mem 0x43000000-0x43ffffff]
[    4.792153] pci 0003:00:00.0: reg 0x14: [mem
0x1020000000-0x102fffffff 64bit pref]
[    4.814022] pci 0003:00:00.0: reg 0x1c: [mem
0x1030000000-0x1031ffffff 64bit pref]
[    4.854830] pci 0003:00:00.0: Enabling HDA controller
[    4.869665] pci 0003:00:00.0: vgaarb: VGA device added:
decodes=io+mem,owns=mem,locks=none
[    4.879399] pci 0003:00:00.0: BAR 1: assigned [mem
0x1020000000-0x102fffffff 64bit pref]
[    4.903880] pci 0003:00:00.0: BAR 3: assigned [mem
0x1030000000-0x1031ffffff 64bit pref]
[    4.927977] pci 0003:00:00.0: BAR 0: assigned [mem 0x43000000-0x43ffffff]
[    4.938162] sysfs: cannot create duplicate filename
'/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/47505500-0003-0000-3130-444531334632/pci0003:00/0003:00:00.0/config'
[    4.951818] CPU: 0 PID: 135 Comm: kworker/0:2 Not tainted
5.4.0-1061-azure #64~18.04.1-Ubuntu
[    4.951820] Hardware name: Microsoft Corporation Virtual
Machine/Virtual Machine, BIOS 090007  06/02/2017
[    4.955812] Workqueue: hv_pri_chan vmbus_add_channel_work
[    4.955812] Call Trace:
[    4.955812]  dump_stack+0x57/0x6d
[    4.955812]  sysfs_warn_dup+0x5b/0x70
[    4.955812]  sysfs_add_file_mode_ns+0x158/0x180
[    4.955812]  sysfs_create_bin_file+0x64/0x90
[    4.955812]  pci_create_sysfs_dev_files+0x72/0x270
[    4.955812]  pci_bus_add_device+0x30/0x80
[    4.955812]  pci_bus_add_devices+0x31/0x70
[    4.955812]  hv_pci_probe+0x48c/0x650
[    4.955812]  vmbus_probe+0x3e/0x90
[    4.955812]  really_probe+0xf5/0x440
[    4.955812]  driver_probe_device+0x11b/0x130
[    4.955812]  __device_attach_driver+0x7b/0xe0
[    4.955812]  ? driver_allows_async_probing+0x60/0x60
[    4.955812]  bus_for_each_drv+0x6e/0xb0
[    4.955812]  __device_attach+0xe4/0x160
[    4.955812]  device_initial_probe+0x13/0x20
[    4.955812]  bus_probe_device+0x92/0xa0
[    4.955812]  device_add+0x402/0x690
[    4.955812]  device_register+0x1a/0x20
[    4.955812]  vmbus_device_register+0x5e/0xf0
[    4.955812]  vmbus_add_channel_work+0x2c4/0x640
[    4.955812]  process_one_work+0x209/0x400
[    4.955812]  worker_thread+0x34/0x400
[    4.955812]  kthread+0x121/0x140
[    4.955812]  ? process_one_work+0x400/0x400
[    4.955812]  ? kthread_park+0x90/0x90
[    4.955812]  ret_from_fork+0x35/0x40

Thanks,
Dexuan

Re: PCI: Race condition in pci_create_sysfs_dev_files

[Krzysztof Wilczyński]

[+CC Adding Sasha for visibility]

Hello,

I am terribly sorry for a very late reply!

[...]
> I think we're seeing the same issue with a Linux VM on Hyper-V.

Are you still seeing this issue happen?  If so, does it happen often?

We haven't had a report from a system that runs as a hypervisor guest
before.  I also assume this is x86 or x86_64 platform, correct?

> Here the kernel is
> https://git.launchpad.net/~canonical-kernel/ubuntu/+source/linux-azure/+git/bionic/tree/?h=Ubuntu-azure-5.4-5.4.0-1061.64_18.04.1

This is quite an old kernel, however the 5.4 is a long-term kernel, and
therefore we need to make sure that it would also work properly.

> '/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/47505500-0003-0000-3130-444531334632/pci0003:00/0003:00:00.0/config'

Following the commit e1d3f3268b0e ("PCI/sysfs: Convert "config" to static
attribute"), the issue particularly with the "config" attribute should be
resolved, thus more modern kernel versions are no long suffer from the race
condition related to this specific and some other problematic attributes.

We quite likely have to back-port these changes to a number of older
long-term kernels.  I am going to look into it.

Hopefully, once the patches land in upstream long-term kernels, then
distributions would be able to cherry-pick them and apply to their kernels
releases.

	Krzysztof

RE: PCI: Race condition in pci_create_sysfs_dev_files

[Dexuan Cui]

> From: Krzysztof Wilczyński <kw@linux.com>
> Sent: Wednesday, November 17, 2021 7:10 PM
> [...]
> > I think we're seeing the same issue with a Linux VM on Hyper-V.
> 
> Are you still seeing this issue happen?  If so, does it happen often?

This doesn't happen often. It's found by our test team.

> We haven't had a report from a system that runs as a hypervisor guest
> before.  I also assume this is x86 or x86_64 platform, correct?

Yes, x86_64.
 
> > Here the kernel is ...
> >
> This is quite an old kernel, however the 5.4 is a long-term kernel, and
> therefore we need to make sure that it would also work properly.
> 
> >
> '/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/475
> 05500-0003-0000-3130-444531334632/pci0003:00/0003:00:00.0/config'
> 
> Following the commit e1d3f3268b0e ("PCI/sysfs: Convert "config" to static
> attribute"), the issue particularly with the "config" attribute should be
> resolved, thus more modern kernel versions are no long suffer from the race
> condition related to this specific and some other problematic attributes.

Thanks for sharing the commit info! It's great to know this has been fixed
in the mainlinekernel.

> We quite likely have to back-port these changes to a number of older
> long-term kernels.  I am going to look into it.

Sounds good! Thank you, Krzysztof!

> Hopefully, once the patches land in upstream long-term kernels, then
> distributions would be able to cherry-pick them and apply to their kernels
> releases.
> 
> 	Krzysztof

Yes, this should work.

Thanks,
-- Dexuan