USB device disconnects on resume

USB device disconnects on resume

[Martin Kepplinger]

hi,

I'm seeing resets and re-enumerations on runtime-resume for one device
a lot. It's a modem connected to the USB2642 Microchip (SMSC) USB2 hub,
that's connected to an xhci HC.

A remote wakeup *sometimes* makes the hub say "physically disconnected"
during resume in hub_activate(), and thus sets reset_resume. Then the
device comes up as low-speed device once, which again is not allowed
during normal runtime resume, so would itself trigger a reset.

The Hub and device is permanently connected on the PCB, so the hub is
interpreting it in a wrong way. I found an email that describes what I
see from Sarah Sharp in 2013 here:
https://marc.info/?l=linux-usb&m=137754385421825&w=2 Where she says:

"Occasionally, the host controller was sending the SoFs too soon on
resume, and the device would interpret it as a low-speed chirp.  The
device would disconnect, and transform from a high speed device to a
low speed device.  I don't think increasing the 10 ms time out will
help at all in this case, but you did ask what USB device disconnect
scenarios I've seen."

I can't find any reference to that bug yet. Has anyone experienced
something (similar) and knows where I can at least try to work around
that?

I don't know Sarahs' current email, could we forward this question to
her?

thank a lot,

                             martin

Re: USB device disconnects on resume

[Alan Stern]

On Tue, Apr 19, 2022 at 11:28:21AM +0200, Martin Kepplinger wrote:
> hi,
> 
> I'm seeing resets and re-enumerations on runtime-resume for one device
> a lot. It's a modem connected to the USB2642 Microchip (SMSC) USB2 hub,
> that's connected to an xhci HC.
> 
> A remote wakeup *sometimes* makes the hub say "physically disconnected"
> during resume in hub_activate(), and thus sets reset_resume. Then the
> device comes up as low-speed device once, which again is not allowed
> during normal runtime resume, so would itself trigger a reset.

Does the reset-resume always fail in this way?

> The Hub and device is permanently connected on the PCB, so the hub is
> interpreting it in a wrong way.

What is the hub is interpreting in a wrong way?  Why should a permanent 
connection on the PCB have anything to do with whether the resume 
signals are misinterpreted?

>  I found an email that describes what I
> see from Sarah Sharp in 2013 here:
> https://marc.info/?l=linux-usb&m=137754385421825&w=2 Where she says:
> 
> "Occasionally, the host controller was sending the SoFs too soon on
> resume, and the device would interpret it as a low-speed chirp.  The
> device would disconnect, and transform from a high speed device to a
> low speed device.  I don't think increasing the 10 ms time out will
> help at all in this case, but you did ask what USB device disconnect
> scenarios I've seen."

Read the following messages in that email thread.  Sarah said that she 
would fix the SoF signal timing in xhci-hcd ("I agree that this seems 
like an xHCI driver issue, and I'll fix it in the driver").  I have no 
idea whether this helped the faulty devices; my guess is that it didn't.

(She never did respond to my comment that there is no such thing as a 
"low-speed chirp".)

> I can't find any reference to that bug yet. Has anyone experienced
> something (similar) and knows where I can at least try to work around
> that?
> 
> I don't know Sarahs' current email, could we forward this question to
> her?

Sarah hasn't worked on Linux or xhci-hcd for many years.  It's probably 
not worth trying to ask her about this.

Alan Stern

Re: USB device disconnects on resume

[Martin Kepplinger]

Am Dienstag, dem 19.04.2022 um 10:32 -0400 schrieb Alan Stern:
> On Tue, Apr 19, 2022 at 11:28:21AM +0200, Martin Kepplinger wrote:
> > hi,
> > 
> > I'm seeing resets and re-enumerations on runtime-resume for one
> > device
> > a lot. It's a modem connected to the USB2642 Microchip (SMSC) USB2
> > hub,
> > that's connected to an xhci HC.
> > 
> > A remote wakeup *sometimes* makes the hub say "physically
> > disconnected"
> > during resume in hub_activate(), and thus sets reset_resume. Then
> > the
> > device comes up as low-speed device once, which again is not
> > allowed
> > during normal runtime resume, so would itself trigger a reset.
> 
> Does the reset-resume always fail in this way?

Resetting itself doesn't usually fail in the sense that a device would
not work anymore after resetting. The problem is that the resets happen
in the first place. 90+% of runtime-resumes are fine - auto- and
wakeup-resume. Resetting is a major problem though, imagine a modem
device being re-enumerated during a phone call or "realtime" data
connection. I see that a lot.

Let me record what hub.c says when leading up to the reset of 1-1.2
(the modem), with logs of a normal runtime resume/suspend cycle
included before that, as reference:

1650447001.174798 pureos kernel: usb 1-1: usb auto-resume
1650447001.242810 pureos kernel: usb 1-1: Waited 0ms for CONNECT
1650447001.247853 pureos kernel: usb 1-1: finish resume
1650447001.249697 pureos kernel: hub 1-1:1.0: hub_resume
1650447001.251409 pureos kernel: usb 1-1-port1: status 0507 change 0000
1650447001.251624 pureos kernel: usb 1-1-port2: status 0507 change 0000
1650447001.251793 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg 0000
evt 0000
1650447001.253052 pureos kernel: usb 1-1.2: usb auto-resume
1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
1650447001.324925 pureos kernel: usb 1-1.2: finish resume
1650447003.831095 pureos kernel: usb 1-1.2: usb auto-suspend, wakeup 1
1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend, wakeup 1
1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume
1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for CONNECT
1650447003.945755 pureos kernel: usb 1-1: finish resume
1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
1650447003.949226 pureos kernel: usb 1-1-port1: status 0507 change 0000
1650447003.949430 pureos kernel: usb 1-1-port2: status 0101 change 0005
1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg 0004
evt 0000
1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-resume
1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
1650447004.097255 pureos kernel: usb 1-1.2: finish reset-resume
1650447004.182333 pureos kernel: usb 1-1.2: reset high-speed USB device
number 5 using xhci-hcd
1650447004.314425 pureos kernel: usb 1-1-port2: resume, status 0
1650447004.317628 pureos kernel: usb 1-1-port2: status 0101, change
0004, 12 Mb/s
1650447004.318673 pureos kernel: usb 1-1.2: USB disconnect, device
number 5
1650447004.323374 pureos kernel: usb 1-1.2: unregistering device


So before resetting, the hub reads
"usb 1-1-port2: status 0101 change 0005" instead of normally
"usb 1-1-port2: status 0507 change 0000"

but I don't know why. That portstatus/portchange doesn't change over
time when I just keep reading portstatus/portchange in hub_activate()
in a loop.


> 
> > The Hub and device is permanently connected on the PCB, so the hub
> > is
> > interpreting it in a wrong way.
> 
> What is the hub is interpreting in a wrong way?  Why should a
> permanent 
> connection on the PCB have anything to do with whether the resume 
> signals are misinterpreted?

I only wanted to say that the device (modem in this case) cannot be
unplugged - there's no plug. That's all :)
https://elixir.bootlin.com/linux/latest/source/drivers/usb/core/hub.c#L1197
interprets my situation as a "removed" device.

> 
> >  I found an email that describes what I
> > see from Sarah Sharp in 2013 here:
> > https://marc.info/?l=linux-usb&m=137754385421825&w=2 Where she
> > says:
> > 
> > "Occasionally, the host controller was sending the SoFs too soon on
> > resume, and the device would interpret it as a low-speed chirp. 
> > The
> > device would disconnect, and transform from a high speed device to
> > a
> > low speed device.  I don't think increasing the 10 ms time out will
> > help at all in this case, but you did ask what USB device
> > disconnect
> > scenarios I've seen."
> 
> Read the following messages in that email thread.  Sarah said that
> she 
> would fix the SoF signal timing in xhci-hcd ("I agree that this seems
> like an xHCI driver issue, and I'll fix it in the driver").  I have
> no 
> idea whether this helped the faulty devices; my guess is that it
> didn't.

Do you know with what changes she tried to fix that?

> 
> (She never did respond to my comment that there is no such thing as a
> "low-speed chirp".)
> 
> > I can't find any reference to that bug yet. Has anyone experienced
> > something (similar) and knows where I can at least try to work
> > around
> > that?
> > 
> > I don't know Sarahs' current email, could we forward this question
> > to
> > her?
> 
> Sarah hasn't worked on Linux or xhci-hcd for many years.  It's
> probably 
> not worth trying to ask her about this.
> 
> Alan Stern

Re: USB device disconnects on resume

[Alan Stern]

On Wed, Apr 20, 2022 at 12:37:36PM +0200, Martin Kepplinger wrote:
> Am Dienstag, dem 19.04.2022 um 10:32 -0400 schrieb Alan Stern:
> > On Tue, Apr 19, 2022 at 11:28:21AM +0200, Martin Kepplinger wrote:
> > > hi,
> > > 
> > > I'm seeing resets and re-enumerations on runtime-resume for one
> > > device
> > > a lot. It's a modem connected to the USB2642 Microchip (SMSC) USB2
> > > hub,
> > > that's connected to an xhci HC.
> > > 
> > > A remote wakeup *sometimes* makes the hub say "physically
> > > disconnected"
> > > during resume in hub_activate(), and thus sets reset_resume. Then
> > > the
> > > device comes up as low-speed device once, which again is not
> > > allowed
> > > during normal runtime resume, so would itself trigger a reset.
> > 
> > Does the reset-resume always fail in this way?
> 
> Resetting itself doesn't usually fail in the sense that a device would
> not work anymore after resetting. The problem is that the resets happen
> in the first place. 90+% of runtime-resumes are fine - auto- and
> wakeup-resume. Resetting is a major problem though, imagine a modem
> device being re-enumerated during a phone call or "realtime" data
> connection. I see that a lot.

Okay, I see.

> Let me record what hub.c says when leading up to the reset of 1-1.2
> (the modem), with logs of a normal runtime resume/suspend cycle
> included before that, as reference:
> 
> 1650447001.174798 pureos kernel: usb 1-1: usb auto-resume
> 1650447001.242810 pureos kernel: usb 1-1: Waited 0ms for CONNECT
> 1650447001.247853 pureos kernel: usb 1-1: finish resume
> 1650447001.249697 pureos kernel: hub 1-1:1.0: hub_resume
> 1650447001.251409 pureos kernel: usb 1-1-port1: status 0507 change 0000
> 1650447001.251624 pureos kernel: usb 1-1-port2: status 0507 change 0000
> 1650447001.251793 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg 0000
> evt 0000
> 1650447001.253052 pureos kernel: usb 1-1.2: usb auto-resume

What is the cause of this runtime resume?  According to the port status 
above, the 1-1.2 device did not send a wakeup request.

> 1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
> 1650447001.324925 pureos kernel: usb 1-1.2: finish resume
> 1650447003.831095 pureos kernel: usb 1-1.2: usb auto-suspend, wakeup 1
> 1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
> 1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend, wakeup 1
> 1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume

This wakeup occurred only 48 ms after the hub was runtime suspended.  
But here at least the cause is evident: The hub sent a wakeup request 
because its child (the 1-1.2 modem) disconnected.

> 1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for CONNECT
> 1650447003.945755 pureos kernel: usb 1-1: finish resume
> 1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
> 1650447003.949226 pureos kernel: usb 1-1-port1: status 0507 change 0000
> 1650447003.949430 pureos kernel: usb 1-1-port2: status 0101 change 0005
> 1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg 0004
> evt 0000
> 1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-resume
> 1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
> 1650447004.097255 pureos kernel: usb 1-1.2: finish reset-resume
> 1650447004.182333 pureos kernel: usb 1-1.2: reset high-speed USB device
> number 5 using xhci-hcd
> 1650447004.314425 pureos kernel: usb 1-1-port2: resume, status 0
> 1650447004.317628 pureos kernel: usb 1-1-port2: status 0101, change
> 0004, 12 Mb/s
> 1650447004.318673 pureos kernel: usb 1-1.2: USB disconnect, device
> number 5
> 1650447004.323374 pureos kernel: usb 1-1.2: unregistering device

And it looks like in this case, the reset-resume failed.

> So before resetting, the hub reads
> "usb 1-1-port2: status 0101 change 0005" instead of normally
> "usb 1-1-port2: status 0507 change 0000"
> 
> but I don't know why. That portstatus/portchange doesn't change over
> time when I just keep reading portstatus/portchange in hub_activate()
> in a loop.

You mean that if the port status and change values are originally 
0101 and 0005 in hub_activate(), they remain equal to those values?  And 
similarly if they are originally 0507 and 0000?

That is to be expected.  Nothing happens to make those values change 
until hub_activate() sends some commands to the hub.

> > > The Hub and device is permanently connected on the PCB, so the hub
> > > is
> > > interpreting it in a wrong way.
> > 
> > What is the hub is interpreting in a wrong way?  Why should a
> > permanent 
> > connection on the PCB have anything to do with whether the resume 
> > signals are misinterpreted?
> 
> I only wanted to say that the device (modem in this case) cannot be
> unplugged - there's no plug. That's all :)
> https://elixir.bootlin.com/linux/latest/source/drivers/usb/core/hub.c#L1197
> interprets my situation as a "removed" device.

What it means is that the modem was electronically disconnected from the 
USB bus.  In theory this could be the result of a mixup in the resume 
signals, but it's more likely that the modem did this deliberately 
because its firmware crashed.  (Why it should crash while it is 
suspended is a good question, though...)

> > >  I found an email that describes what I
> > > see from Sarah Sharp in 2013 here:
> > > https://marc.info/?l=linux-usb&m=137754385421825&w=2 Where she
> > > says:
> > > 
> > > "Occasionally, the host controller was sending the SoFs too soon on
> > > resume, and the device would interpret it as a low-speed chirp. 
> > > The
> > > device would disconnect, and transform from a high speed device to
> > > a
> > > low speed device.  I don't think increasing the 10 ms time out will
> > > help at all in this case, but you did ask what USB device
> > > disconnect
> > > scenarios I've seen."
> > 
> > Read the following messages in that email thread.  Sarah said that
> > she 
> > would fix the SoF signal timing in xhci-hcd ("I agree that this seems
> > like an xHCI driver issue, and I'll fix it in the driver").  I have
> > no 
> > idea whether this helped the faulty devices; my guess is that it
> > didn't.
> 
> Do you know with what changes she tried to fix that?

No.  But you ought to be able to see by checking the history for that 
time period.

Alan Stern

Re: USB device disconnects on resume

[Martin Kepplinger]

Am Mittwoch, dem 20.04.2022 um 10:40 -0400 schrieb Alan Stern:
> On Wed, Apr 20, 2022 at 12:37:36PM +0200, Martin Kepplinger wrote:
> > Am Dienstag, dem 19.04.2022 um 10:32 -0400 schrieb Alan Stern:
> > > On Tue, Apr 19, 2022 at 11:28:21AM +0200, Martin Kepplinger
> > > wrote:
> > > > hi,
> > > > 
> > > > I'm seeing resets and re-enumerations on runtime-resume for one
> > > > device
> > > > a lot. It's a modem connected to the USB2642 Microchip (SMSC)
> > > > USB2
> > > > hub,
> > > > that's connected to an xhci HC.
> > > > 
> > > > A remote wakeup *sometimes* makes the hub say "physically
> > > > disconnected"
> > > > during resume in hub_activate(), and thus sets reset_resume.
> > > > Then
> > > > the
> > > > device comes up as low-speed device once, which again is not
> > > > allowed
> > > > during normal runtime resume, so would itself trigger a reset.
> > > 
> > > Does the reset-resume always fail in this way?
> > 
> > Resetting itself doesn't usually fail in the sense that a device
> > would
> > not work anymore after resetting. The problem is that the resets
> > happen
> > in the first place. 90+% of runtime-resumes are fine - auto- and
> > wakeup-resume. Resetting is a major problem though, imagine a modem
> > device being re-enumerated during a phone call or "realtime" data
> > connection. I see that a lot.
> 
> Okay, I see.
> 
> > Let me record what hub.c says when leading up to the reset of 1-1.2
> > (the modem), with logs of a normal runtime resume/suspend cycle
> > included before that, as reference:
> > 
> > 1650447001.174798 pureos kernel: usb 1-1: usb auto-resume
> > 1650447001.242810 pureos kernel: usb 1-1: Waited 0ms for CONNECT
> > 1650447001.247853 pureos kernel: usb 1-1: finish resume
> > 1650447001.249697 pureos kernel: hub 1-1:1.0: hub_resume
> > 1650447001.251409 pureos kernel: usb 1-1-port1: status 0507 change
> > 0000
> > 1650447001.251624 pureos kernel: usb 1-1-port2: status 0507 change
> > 0000
> > 1650447001.251793 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg
> > 0000
> > evt 0000
> > 1650447001.253052 pureos kernel: usb 1-1.2: usb auto-resume
> 
> What is the cause of this runtime resume?  According to the port
> status 
> above, the 1-1.2 device did not send a wakeup request.

How would I find out? Recording via usbmon is next on my todo list.

> 
> > 1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
> > 1650447001.324925 pureos kernel: usb 1-1.2: finish resume
> > 1650447003.831095 pureos kernel: usb 1-1.2: usb auto-suspend,
> > wakeup 1
> > 1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
> > 1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend, wakeup
> > 1
> > 1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume
> 
> This wakeup occurred only 48 ms after the hub was runtime suspended. 
> But here at least the cause is evident: The hub sent a wakeup request
> because its child (the 1-1.2 modem) disconnected.

fwiw, that wakeup-resume *always* comes about 50 ms after the last
runtime suspend.

> 
> > 1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for CONNECT
> > 1650447003.945755 pureos kernel: usb 1-1: finish resume
> > 1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
> > 1650447003.949226 pureos kernel: usb 1-1-port1: status 0507 change
> > 0000
> > 1650447003.949430 pureos kernel: usb 1-1-port2: status 0101 change
> > 0005
> > 1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg
> > 0004
> > evt 0000
> > 1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-resume
> > 1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
> > 1650447004.097255 pureos kernel: usb 1-1.2: finish reset-resume
> > 1650447004.182333 pureos kernel: usb 1-1.2: reset high-speed USB
> > device
> > number 5 using xhci-hcd
> > 1650447004.314425 pureos kernel: usb 1-1-port2: resume, status 0
> > 1650447004.317628 pureos kernel: usb 1-1-port2: status 0101, change
> > 0004, 12 Mb/s
> > 1650447004.318673 pureos kernel: usb 1-1.2: USB disconnect, device
> > number 5
> > 1650447004.323374 pureos kernel: usb 1-1.2: unregistering device
> 
> And it looks like in this case, the reset-resume failed.

Well, at least reset_resume has been set, which I want to avoid.

> 
> > So before resetting, the hub reads
> > "usb 1-1-port2: status 0101 change 0005" instead of normally
> > "usb 1-1-port2: status 0507 change 0000"
> > 
> > but I don't know why. That portstatus/portchange doesn't change
> > over
> > time when I just keep reading portstatus/portchange in
> > hub_activate()
> > in a loop.
> 
> You mean that if the port status and change values are originally 
> 0101 and 0005 in hub_activate(), they remain equal to those values? 
> And 
> similarly if they are originally 0507 and 0000?
> 
> That is to be expected.  Nothing happens to make those values change 
> until hub_activate() sends some commands to the hub.

I see.

Of course this doesn't make much sense, but just so you know: if I just
don't let hub_activate() set udev->reset_resume to 1, then
check_port_resume_type() will do so, and thus again
finish_port_resume() will reset the device by calling
usb_reset_and_verify_device().

> 
> > > > The Hub and device is permanently connected on the PCB, so the
> > > > hub
> > > > is
> > > > interpreting it in a wrong way.
> > > 
> > > What is the hub is interpreting in a wrong way?  Why should a
> > > permanent 
> > > connection on the PCB have anything to do with whether the resume
> > > signals are misinterpreted?
> > 
> > I only wanted to say that the device (modem in this case) cannot be
> > unplugged - there's no plug. That's all :)
> >      
> > https://elixir.bootlin.com/linux/latest/source/drivers/usb/core/hub.c#L1197
> > interprets my situation as a "removed" device.
> 
> What it means is that the modem was electronically disconnected from
> the 
> USB bus.  In theory this could be the result of a mixup in the resume
> signals, but it's more likely that the modem did this deliberately 
> because its firmware crashed.  (Why it should crash while it is 
> suspended is a good question, though...)

ok. assuming such a firmware bug, if I set a new quirk for the device,
do you think I can work around that (in hub.c?) in a way that userspace
doesn't really notice?

In theory, if I know this behaviour in advance, I think I should be
able to somehow wait until the device is ready again instead of
resetting.


> 
> > > >  I found an email that describes what I
> > > > see from Sarah Sharp in 2013 here:
> > > > https://marc.info/?l=linux-usb&m=137754385421825&w=2 Where she
> > > > says:
> > > > 
> > > > "Occasionally, the host controller was sending the SoFs too
> > > > soon on
> > > > resume, and the device would interpret it as a low-speed
> > > > chirp. 
> > > > The
> > > > device would disconnect, and transform from a high speed device
> > > > to
> > > > a
> > > > low speed device.  I don't think increasing the 10 ms time out
> > > > will
> > > > help at all in this case, but you did ask what USB device
> > > > disconnect
> > > > scenarios I've seen."
> > > 
> > > Read the following messages in that email thread.  Sarah said
> > > that
> > > she 
> > > would fix the SoF signal timing in xhci-hcd ("I agree that this
> > > seems
> > > like an xHCI driver issue, and I'll fix it in the driver").  I
> > > have
> > > no 
> > > idea whether this helped the faulty devices; my guess is that it
> > > didn't.
> > 
> > Do you know with what changes she tried to fix that?
> 
> No.  But you ought to be able to see by checking the history for that
> time period.
> 
> Alan Stern

Re: USB device disconnects on resume

[Alan Stern]

On Thu, Apr 21, 2022 at 12:38:56PM +0200, Martin Kepplinger wrote:
> Am Mittwoch, dem 20.04.2022 um 10:40 -0400 schrieb Alan Stern:
> > On Wed, Apr 20, 2022 at 12:37:36PM +0200, Martin Kepplinger wrote:
> > > Resetting itself doesn't usually fail in the sense that a device
> > > would
> > > not work anymore after resetting. The problem is that the resets
> > > happen
> > > in the first place. 90+% of runtime-resumes are fine - auto- and
> > > wakeup-resume. Resetting is a major problem though, imagine a modem
> > > device being re-enumerated during a phone call or "realtime" data
> > > connection. I see that a lot.
> > 
> > Okay, I see.

By the way, I assume that while resetting the modem is a major problem 
for your potential use cases, having it crash with no hope of recovery 
is even worse.  But maybe I'm wrong...

> > > Let me record what hub.c says when leading up to the reset of 1-1.2
> > > (the modem), with logs of a normal runtime resume/suspend cycle
> > > included before that, as reference:
> > > 
> > > 1650447001.174798 pureos kernel: usb 1-1: usb auto-resume
> > > 1650447001.242810 pureos kernel: usb 1-1: Waited 0ms for CONNECT
> > > 1650447001.247853 pureos kernel: usb 1-1: finish resume
> > > 1650447001.249697 pureos kernel: hub 1-1:1.0: hub_resume
> > > 1650447001.251409 pureos kernel: usb 1-1-port1: status 0507 change
> > > 0000
> > > 1650447001.251624 pureos kernel: usb 1-1-port2: status 0507 change
> > > 0000
> > > 1650447001.251793 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg
> > > 0000
> > > evt 0000
> > > 1650447001.253052 pureos kernel: usb 1-1.2: usb auto-resume
> > 
> > What is the cause of this runtime resume?  According to the port
> > status 
> > above, the 1-1.2 device did not send a wakeup request.
> 
> How would I find out? Recording via usbmon is next on my todo list.

That's a good thing to try in any case.

I asked because it seemed possible that you had manually caused the 
resume somehow.

> > > 1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
> > > 1650447001.324925 pureos kernel: usb 1-1.2: finish resume
> > > 1650447003.831095 pureos kernel: usb 1-1.2: usb auto-suspend,
> > > wakeup 1
> > > 1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
> > > 1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend, wakeup
> > > 1
> > > 1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume
> > 
> > This wakeup occurred only 48 ms after the hub was runtime suspended. 
> > But here at least the cause is evident: The hub sent a wakeup request
> > because its child (the 1-1.2 modem) disconnected.
> 
> fwiw, that wakeup-resume *always* comes about 50 ms after the last
> runtime suspend.

Maybe the modem's firmware has some 50-ms timeout that expires and then 
causes the crash.

> > > 1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for CONNECT
> > > 1650447003.945755 pureos kernel: usb 1-1: finish resume
> > > 1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
> > > 1650447003.949226 pureos kernel: usb 1-1-port1: status 0507 change
> > > 0000
> > > 1650447003.949430 pureos kernel: usb 1-1-port2: status 0101 change
> > > 0005
> > > 1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg
> > > 0004
> > > evt 0000
> > > 1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-resume
> > > 1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
> > > 1650447004.097255 pureos kernel: usb 1-1.2: finish reset-resume
> > > 1650447004.182333 pureos kernel: usb 1-1.2: reset high-speed USB
> > > device
> > > number 5 using xhci-hcd
> > > 1650447004.314425 pureos kernel: usb 1-1-port2: resume, status 0
> > > 1650447004.317628 pureos kernel: usb 1-1-port2: status 0101, change
> > > 0004, 12 Mb/s
> > > 1650447004.318673 pureos kernel: usb 1-1.2: USB disconnect, device
> > > number 5
> > > 1650447004.323374 pureos kernel: usb 1-1.2: unregistering device
> > 
> > And it looks like in this case, the reset-resume failed.
> 
> Well, at least reset_resume has been set, which I want to avoid.

Do you mean you would prefer to have the modem disconnect permanently 
(or at least until the next reboot)?

> > > So before resetting, the hub reads
> > > "usb 1-1-port2: status 0101 change 0005" instead of normally
> > > "usb 1-1-port2: status 0507 change 0000"
> > > 
> > > but I don't know why. That portstatus/portchange doesn't change
> > > over
> > > time when I just keep reading portstatus/portchange in
> > > hub_activate()
> > > in a loop.
> > 
> > You mean that if the port status and change values are originally 
> > 0101 and 0005 in hub_activate(), they remain equal to those values? 
> > And 
> > similarly if they are originally 0507 and 0000?
> > 
> > That is to be expected.  Nothing happens to make those values change 
> > until hub_activate() sends some commands to the hub.
> 
> I see.
> 
> Of course this doesn't make much sense, but just so you know: if I just
> don't let hub_activate() set udev->reset_resume to 1, then
> check_port_resume_type() will do so, and thus again
> finish_port_resume() will reset the device by calling
> usb_reset_and_verify_device().

Yeah, there's some redundancy in there.  The core really tries pretty 
hard to make sure that devices don't get lost just because they have 
trouble handling a suspend + resume.

> > What it means is that the modem was electronically disconnected from
> > the 
> > USB bus.  In theory this could be the result of a mixup in the resume
> > signals, but it's more likely that the modem did this deliberately 
> > because its firmware crashed.  (Why it should crash while it is 
> > suspended is a good question, though...)
> 
> ok. assuming such a firmware bug, if I set a new quirk for the device,
> do you think I can work around that (in hub.c?) in a way that userspace
> doesn't really notice?

One thing you can do pretty easily, without changing the kernel, is 
prevent the modem from going into runtime suspend in the first place.  
For example, if you have a program like powertop overseeing your runtime 
power management, you could tell it not to let the modem suspend.  Or if 
you want to set it up by hand, the command is:

	echo on >/sys/bus/usb/devices/.../power/control

(where "..." is the appropriate path for the modem device, such as 
"1-1.2").  You can even write a udev script to do this automatically 
whenever the modem is detected.

> In theory, if I know this behaviour in advance, I think I should be
> able to somehow wait until the device is ready again instead of
> resetting.

What if the modem never becomes ready again (or not until you reboot)?  
I think that sort of behavior is not at all unlikely.  You can test this 
by disabling the code in finish_port_resume() that does reset-resumes.

Alan Stern

Re: USB device disconnects on resume

[Martin Kepplinger]

[-- Attachment #1: Type: text/plain, Size: 9021 bytes --]

Alan, thanks so much for asking these questions and thinking this
through! It helps.

Am Donnerstag, dem 21.04.2022 um 10:24 -0400 schrieb Alan Stern:
> On Thu, Apr 21, 2022 at 12:38:56PM +0200, Martin Kepplinger wrote:
> > Am Mittwoch, dem 20.04.2022 um 10:40 -0400 schrieb Alan Stern:
> > > On Wed, Apr 20, 2022 at 12:37:36PM +0200, Martin Kepplinger
> > > wrote:
> > > > Resetting itself doesn't usually fail in the sense that a
> > > > device
> > > > would
> > > > not work anymore after resetting. The problem is that the
> > > > resets
> > > > happen
> > > > in the first place. 90+% of runtime-resumes are fine - auto-
> > > > and
> > > > wakeup-resume. Resetting is a major problem though, imagine a
> > > > modem
> > > > device being re-enumerated during a phone call or "realtime"
> > > > data
> > > > connection. I see that a lot.
> > > 
> > > Okay, I see.
> 
> By the way, I assume that while resetting the modem is a major
> problem 
> for your potential use cases, having it crash with no hope of
> recovery 
> is even worse.  But maybe I'm wrong...

Sure that's true (and I have other usb-related problems too that result
in the xhci HC dying even, when I see "xhci-hcd.4.auto: Port resume
timed out, port 1-1: 0xfe3", so the Hub where the modem is connected)
but these resets are a seperate issue I want to tackle now and see
whether it help with other usb-related problems, so let's focus on this
disconnect/reset situation. So let's not get confused :)

> 
> > > > Let me record what hub.c says when leading up to the reset of
> > > > 1-1.2
> > > > (the modem), with logs of a normal runtime resume/suspend cycle
> > > > included before that, as reference:
> > > > 
> > > > 1650447001.174798 pureos kernel: usb 1-1: usb auto-resume
> > > > 1650447001.242810 pureos kernel: usb 1-1: Waited 0ms for
> > > > CONNECT
> > > > 1650447001.247853 pureos kernel: usb 1-1: finish resume
> > > > 1650447001.249697 pureos kernel: hub 1-1:1.0: hub_resume
> > > > 1650447001.251409 pureos kernel: usb 1-1-port1: status 0507
> > > > change
> > > > 0000
> > > > 1650447001.251624 pureos kernel: usb 1-1-port2: status 0507
> > > > change
> > > > 0000
> > > > 1650447001.251793 pureos kernel: hub 1-1:1.0: state 7 ports 3
> > > > chg
> > > > 0000
> > > > evt 0000
> > > > 1650447001.253052 pureos kernel: usb 1-1.2: usb auto-resume
> > > 
> > > What is the cause of this runtime resume?  According to the port
> > > status 
> > > above, the 1-1.2 device did not send a wakeup request.
> > 
> > How would I find out? Recording via usbmon is next on my todo list.
> 
> That's a good thing to try in any case.
> 
> I asked because it seemed possible that you had manually caused the 
> resume somehow.

I use the modem "a lot" in order to wake it up often, that's all.

> 
> > > > 1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for
> > > > CONNECT
> > > > 1650447001.324925 pureos kernel: usb 1-1.2: finish resume
> > > > 1650447003.831095 pureos kernel: usb 1-1.2: usb auto-suspend,
> > > > wakeup 1
> > > > 1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
> > > > 1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend,
> > > > wakeup
> > > > 1
> > > > 1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume
> > > 
> > > This wakeup occurred only 48 ms after the hub was runtime
> > > suspended. 
> > > But here at least the cause is evident: The hub sent a wakeup
> > > request
> > > because its child (the 1-1.2 modem) disconnected.
> > 
> > fwiw, that wakeup-resume *always* comes about 50 ms after the last
> > runtime suspend.
> 
> Maybe the modem's firmware has some 50-ms timeout that expires and
> then 
> causes the crash.

I now recorded usbmon (1u) traffic of a similar sequence I sent here,
with a few usbmon-timestamps in the logs:

https://source.puri.sm/Librem5/linux/-/issues/303#note_197913

the usbmon log textfile is attached in that comment link and in this
email.

> 
> > > > 1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for
> > > > CONNECT
> > > > 1650447003.945755 pureos kernel: usb 1-1: finish resume
> > > > 1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
> > > > 1650447003.949226 pureos kernel: usb 1-1-port1: status 0507
> > > > change
> > > > 0000
> > > > 1650447003.949430 pureos kernel: usb 1-1-port2: status 0101
> > > > change
> > > > 0005
> > > > 1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports 3
> > > > chg
> > > > 0004
> > > > evt 0000
> > > > 1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-resume
> > > > 1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for
> > > > CONNECT
> > > > 1650447004.097255 pureos kernel: usb 1-1.2: finish reset-resume
> > > > 1650447004.182333 pureos kernel: usb 1-1.2: reset high-speed
> > > > USB
> > > > device
> > > > number 5 using xhci-hcd
> > > > 1650447004.314425 pureos kernel: usb 1-1-port2: resume, status
> > > > 0
> > > > 1650447004.317628 pureos kernel: usb 1-1-port2: status 0101,
> > > > change
> > > > 0004, 12 Mb/s
> > > > 1650447004.318673 pureos kernel: usb 1-1.2: USB disconnect,
> > > > device
> > > > number 5
> > > > 1650447004.323374 pureos kernel: usb 1-1.2: unregistering
> > > > device
> > > 
> > > And it looks like in this case, the reset-resume failed.
> > 
> > Well, at least reset_resume has been set, which I want to avoid.
> 
> Do you mean you would prefer to have the modem disconnect permanently
> (or at least until the next reboot)?

no. I mean I'd prefer the kernel keep the device usable when such a
disconnect happens - after a short pause until the modem is up again -
and not re-enumerate.

An audio stream is not being interrupted by such a usb disconnect and
if I'd keep the ttyUSB device for userspace, I'd keep an opened ttyUSB
controllable - even if possibly with a large latency spike. That would
stay a bad workaround of course. Do you know what I'm thinking about?

> 
> > > > So before resetting, the hub reads
> > > > "usb 1-1-port2: status 0101 change 0005" instead of normally
> > > > "usb 1-1-port2: status 0507 change 0000"
> > > > 
> > > > but I don't know why. That portstatus/portchange doesn't change
> > > > over
> > > > time when I just keep reading portstatus/portchange in
> > > > hub_activate()
> > > > in a loop.
> > > 
> > > You mean that if the port status and change values are originally
> > > 0101 and 0005 in hub_activate(), they remain equal to those
> > > values? 
> > > And 
> > > similarly if they are originally 0507 and 0000?
> > > 
> > > That is to be expected.  Nothing happens to make those values
> > > change 
> > > until hub_activate() sends some commands to the hub.
> > 
> > I see.
> > 
> > Of course this doesn't make much sense, but just so you know: if I
> > just
> > don't let hub_activate() set udev->reset_resume to 1, then
> > check_port_resume_type() will do so, and thus again
> > finish_port_resume() will reset the device by calling
> > usb_reset_and_verify_device().
> 
> Yeah, there's some redundancy in there.  The core really tries pretty
> hard to make sure that devices don't get lost just because they have 
> trouble handling a suspend + resume.
> 
> > > What it means is that the modem was electronically disconnected
> > > from
> > > the 
> > > USB bus.  In theory this could be the result of a mixup in the
> > > resume
> > > signals, but it's more likely that the modem did this
> > > deliberately 
> > > because its firmware crashed.  (Why it should crash while it is 
> > > suspended is a good question, though...)
> > 
> > ok. assuming such a firmware bug, if I set a new quirk for the
> > device,
> > do you think I can work around that (in hub.c?) in a way that
> > userspace
> > doesn't really notice?
> 
> One thing you can do pretty easily, without changing the kernel, is 
> prevent the modem from going into runtime suspend in the first
> place.  
> For example, if you have a program like powertop overseeing your
> runtime 
> power management, you could tell it not to let the modem suspend.  Or
> if 
> you want to set it up by hand, the command is:
> 
>         echo on >/sys/bus/usb/devices/.../power/control
> 
> (where "..." is the appropriate path for the modem device, such as 
> "1-1.2").  You can even write a udev script to do this automatically 
> whenever the modem is detected.

I know that this "solves" my problems but that also prevents the usb2
hub (1-1) from suspending and that's not a practical solution. The hub
uses a *lot* of power.

> 
> > In theory, if I know this behaviour in advance, I think I should be
> > able to somehow wait until the device is ready again instead of
> > resetting.
> 
> What if the modem never becomes ready again (or not until you
> reboot)?  
> I think that sort of behavior is not at all unlikely.  You can test
> this 
> by disabling the code in finish_port_resume() that does reset-
> resumes.

if I just do that, I get "gone after usb resume? status -5" and thus a
reset is triggered after all (also, when I do msleep(500) instead of
reset_and_verify_device() there).

> 
> Alan Stern


[-- Attachment #2: 1_usbmon.txt --]
[-- Type: text/plain, Size: 17988 bytes --]

ffff0000bf334a00 3411803859 C Bi:1:006:8 -104 0
ffff0000440c2a00 3411804162 C Bi:1:006:8 -104 0
ffff0000440c2500 3411804170 C Bi:1:006:8 -104 0
ffff0000440c2d00 3411804175 C Bi:1:006:8 -104 0
ffff0000440c2900 3411804183 C Bi:1:006:8 -104 0
ffff0000440c2c00 3411804187 C Bi:1:006:8 -104 0
ffff0000440c2f00 3411804193 C Bi:1:006:8 -104 0
ffff00002472de00 3411804201 C Bi:1:006:8 -104 0
ffff0000440c2400 3411804538 C Bi:1:006:8 -104 0
ffff0000440c2600 3411804547 C Bi:1:006:8 -104 0
ffff0000440c2e00 3411804808 C Bi:1:006:8 -104 0
ffff0000440c2b00 3411804817 C Bi:1:006:8 -104 0
ffff0000bf271800 3411804825 C Bi:1:006:8 -104 0
ffff0000440c2200 3411804831 C Bi:1:006:8 -104 0
ffff0000009e9500 3411804837 C Bi:1:006:8 -104 0
ffff0000bf14ba00 3411804845 C Bi:1:006:8 -104 0
ffff0000440c2700 3411804852 C Bi:1:006:8 -104 0
ffff000055d1b600 3411805205 C Bi:1:006:8 -104 0
ffff000055d1b100 3411805212 C Bi:1:006:8 -104 0
ffff000055d1b400 3411805221 C Bi:1:006:8 -104 0
ffff0000520e5a00 3411805227 C Bi:1:006:8 -104 0
ffff0000520e5800 3411805235 C Bi:1:006:8 -104 0
ffff0000520e5700 3411805241 C Bi:1:006:8 -104 0
ffff0000520e5c00 3411805245 C Bi:1:006:8 -104 0
ffff000055d1b800 3411805256 C Bi:1:006:8 -104 0
ffff0000520e5d00 3411805607 C Bi:1:006:8 -104 0
ffff0000520e5500 3411805615 C Bi:1:006:8 -104 0
ffff000047036a00 3411805623 C Bi:1:006:8 -104 0
ffff0000290ee800 3411805630 C Bi:1:006:8 -104 0
ffff00002cc74600 3411805641 C Bi:1:006:8 -104 0
ffff000026ddb900 3411805651 C Bi:1:006:8 -104 0
ffff000000997000 3411805657 C Bi:1:006:8 -104 0
ffff0000520e5600 3411805663 C Bi:1:006:8 -104 0
ffff00000d5fcf00 3411805968 C Bi:1:006:8 -104 0
ffff0000bbf44800 3411805976 C Bi:1:006:8 -104 0
ffff00001fd2d200 3411805986 C Bi:1:006:8 -104 0
ffff00001fd2d300 3411805994 C Bi:1:006:8 -104 0
ffff00000d5fcd00 3411806001 C Bi:1:006:8 -104 0
ffff0000043d0700 3411806369 C Bi:1:006:8 -104 0
ffff0000043d0300 3411806378 C Bi:1:006:8 -104 0
ffff0000043d0f00 3411806392 C Bi:1:006:8 -104 0
ffff0000043d0500 3411806398 C Bi:1:006:8 -104 0
ffff000052e0b800 3411806404 C Bi:1:006:8 -104 0
ffff000052e0b500 3411806412 C Bi:1:006:8 -104 0
ffff000046e8a200 3411806419 C Bi:1:006:8 -104 0
ffff000052e0bb00 3411806709 C Bi:1:006:8 -104 0
ffff000052e0bc00 3411806726 C Bi:1:006:8 -104 0
ffff000052e0b000 3411806734 C Bi:1:006:8 -104 0
ffff000052e0be00 3411806744 C Bi:1:006:8 -104 0
ffff000052e0b200 3411806752 C Bi:1:006:8 -104 0
ffff000046f03c00 3411807093 C Bi:1:006:8 -104 0
ffff000055bfe900 3411807102 C Bi:1:006:8 -104 0
ffff0000bc7ef300 3411807110 C Bi:1:006:8 -104 0
ffff0000bc7ef200 3411807150 C Bi:1:006:8 -104 0
ffff000046f53700 3411807162 C Bi:1:006:8 -104 0
ffff000047399100 3411807167 C Bi:1:006:8 -104 0
ffff000052e0bd00 3411807178 C Bi:1:006:8 -104 0
ffff000047399000 3411807439 C Bi:1:006:8 -104 0
ffff00002472d300 3411807449 C Bi:1:006:8 -104 0
ffff000047399200 3411807455 C Bi:1:006:8 -104 0
ffff0000bbe51d00 3411807962 C Ii:1:006:7 -2:16 0
ffff00004834fc00 3411810266 C Bi:1:006:4 -2 0
ffff0000bc5e0200 3411810461 C Bi:1:006:4 -2 0
ffff0000bc5e0300 3411811398 C Bi:1:006:4 -2 0
ffff0000bc5e0400 3411811595 C Bi:1:006:4 -2 0
ffff00004834f500 3411811793 C Ii:1:006:3 -2:16 0
ffff000031511f00 3411812759 C Bi:1:006:2 -2 0
ffff000031511200 3411813650 C Bi:1:006:2 -2 0
ffff000031511b00 3411814522 C Bi:1:006:2 -2 0
ffff000031511d00 3411814754 C Bi:1:006:2 -2 0
ffff00001fd2df00 3411815721 C Bi:1:006:1 -2 0
ffff00001fd2d000 3411815895 C Bi:1:006:1 -2 0
ffff00000e904100 3411816824 C Bi:1:006:1 -2 0
ffff000014838000 3411817704 C Bi:1:006:1 -2 0
ffff000046f53700 3411817862 S Co:1:006:0 s 00 03 0001 0000 0000 0
ffff000046f53700 3411818894 C Co:1:006:0 0 0
ffff000046f53700 3411818959 S Co:1:002:0 s 23 03 0002 0002 0000 0
ffff000046f53700 3411819071 C Co:1:002:0 0 0
ffff0000befcda00 3411841641 C Ii:1:002:1 -2:2048 0
ffff000046f53700 3411841759 S Co:1:002:0 s 00 03 0001 0000 0000 0
ffff000046f53700 3411841840 C Co:1:002:0 0 0
ffff000046f53700 3411841865 S Co:1:001:0 s 23 03 0002 0001 0000 0
ffff000046f53700 3411864838 C Co:1:001:0 0 0
ffff0000bf035e00 3411888967 C Ii:1:001:1 -2:2048 0
ffff000046f53700 3412240229 S Ci:1:001:0 s a3 00 0000 0001 0004 4 <
ffff000046f53700 3412240507 C Ci:1:001:0 0 4 = 07050000
ffff0000bf035e00 3412240641 S Ii:1:001:1 -115:2048 4 <
ffff0000bf035e00 3412280877 C Ii:1:001:1 0:2048 1 = 02
ffff0000bf035e00 3412281031 S Ii:1:001:1 -115:2048 4 <
ffff000046f53700 3412281339 S Ci:1:001:0 s a3 00 0000 0001 0004 4 <
ffff000046f53700 3412281659 C Ci:1:001:0 0 4 = 03050400
ffff000046f53700 3412281701 S Co:1:001:0 s 23 01 0012 0001 0000 0
ffff000046f53700 3412281729 C Co:1:001:0 0 0
ffff000046f53700 3412300931 S Ci:1:001:0 s a3 00 0000 0001 0004 4 <
ffff000046f53700 3412301029 C Ci:1:001:0 0 4 = 03050000
ffff000046f53700 3412320851 S Ci:1:002:0 s 80 00 0000 0000 0002 2 <
ffff000046f53700 3412321210 C Ci:1:002:0 0 2 = 0300
ffff000046f53700 3412321239 S Co:1:002:0 s 00 01 0001 0000 0000 0
ffff000046f53700 3412321312 C Co:1:002:0 0 0
ffff000046f53700 3412321397 S Ci:1:002:0 s a3 00 0000 0001 0004 4 <
ffff000046f53700 3412321476 C Ci:1:002:0 0 4 = 07050000
ffff000046f53700 3412321536 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff000046f53700 3412321615 C Ci:1:002:0 0 4 = 03050400
ffff000046f53700 3412321657 S Ci:1:002:0 s a3 00 0000 0003 0004 4 <
ffff000046f53700 3412321731 C Ci:1:002:0 0 4 = 00010000
ffff0000befcda00 3412321756 S Ii:1:002:1 -115:2048 1 <
ffff000046f53700 3412322018 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff000046f53700 3412322091 C Ci:1:002:0 0 4 = 03050400
ffff000046f53700 3412322115 S Co:1:002:0 s 23 01 0012 0002 0000 0
ffff000046f53700 3412322171 C Co:1:002:0 0 0
ffff000046f53700 3412341019 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff000046f53700 3412341303 C Ci:1:002:0 0 4 = 03050000
ffff000046f53700 3412360988 S Ci:1:006:0 s 80 00 0000 0000 0002 2 <
ffff000046f53700 3412361457 C Ci:1:006:0 0 2 = 0200
ffff000046f53700 3412361501 S Co:1:006:0 s 00 01 0001 0000 0000 0
ffff000046f53700 3412361679 C Co:1:006:0 0 0
ffff00001fd2df00 3412361790 S Bi:1:006:1 -115 4096 <
ffff00001fd2d000 3412361848 S Bi:1:006:1 -115 4096 <
ffff00000e904100 3412361873 S Bi:1:006:1 -115 4096 <
ffff000014838000 3412361897 S Bi:1:006:1 -115 4096 <
ffff000031511f00 3412361962 S Bi:1:006:2 -115 4096 <
ffff000031511200 3412361997 S Bi:1:006:2 -115 4096 <
ffff000031511b00 3412362024 S Bi:1:006:2 -115 4096 <
ffff000031511d00 3412362051 S Bi:1:006:2 -115 4096 <
ffff00004834f500 3412362117 S Ii:1:006:3 -115:16 64 <
ffff00004834fc00 3412362157 S Bi:1:006:4 -115 4096 <
ffff0000bc5e0200 3412362193 S Bi:1:006:4 -115 4096 <
ffff0000bc5e0300 3412362216 S Bi:1:006:4 -115 4096 <
ffff0000bc5e0400 3412362239 S Bi:1:006:4 -115 4096 <
ffff0000bbe51d00 3412362329 S Ii:1:006:7 -115:16 64 <
ffff000046f53700 3412362447 S Bi:1:006:8 -115 1500 <
ffff000046f53100 3412362504 S Bi:1:006:8 -115 1500 <
ffff000046f53700 3412362575 C Bi:1:006:8 0 588 = 4500024c 5b9e4000 34068f24 55d0612a 0a91985e 2328e8d6 918eb931 83bdb959
ffff000046f53700 3412362634 S Bi:1:006:8 -115 1500 <
ffff000046f53c00 3412362754 S Bi:1:006:8 -115 1500 <
ffff000046f53d00 3412362780 S Bi:1:006:8 -115 1500 <
ffff000046f53a00 3412362806 S Bi:1:006:8 -115 1500 <
ffff000047399200 3412362833 S Bi:1:006:8 -115 1500 <
ffff000047399000 3412362856 S Bi:1:006:8 -115 1500 <
ffff000047399100 3412362883 S Bi:1:006:8 -115 1500 <
ffff0000bc7ef200 3412362911 S Bi:1:006:8 -115 1500 <
ffff0000bc7ef300 3412362941 S Bi:1:006:8 -115 1500 <
ffff000055bfe900 3412362973 S Bi:1:006:8 -115 1500 <
ffff000046e8a200 3412363008 S Bi:1:006:8 -115 1500 <
ffff000052e0bd00 3412363775 S Bo:1:006:5 -115 52 = 45000034 54514000 40068c89 0a91985e 55d0612a e8d62328 83bdb959 918ebb49
ffff000052e0be00 3412364173 S Bi:1:006:8 -115 1500 <
ffff000052e0b200 3412364194 S Bi:1:006:8 -115 1500 <
ffff000052e0b000 3412364231 S Bi:1:006:8 -115 1500 <
ffff000052e0bc00 3412364256 S Bi:1:006:8 -115 1500 <
ffff000052e0bb00 3412364282 S Bi:1:006:8 -115 1500 <
ffff000052e0b500 3412364308 S Bi:1:006:8 -115 1500 <
ffff000052e0b800 3412364335 S Bi:1:006:8 -115 1500 <
ffff00007a7f2d00 3412364390 S Bi:1:006:8 -115 1500 <
ffff00007a7f2100 3412364419 S Bi:1:006:8 -115 1500 <
ffff00007a7f2300 3412364448 S Bi:1:006:8 -115 1500 <
ffff000052e0bd00 3412364477 C Bo:1:006:5 0 52 >
ffff00007a7f2400 3412364623 S Bi:1:006:8 -115 1500 <
ffff00007a7f2c00 3412364654 S Bi:1:006:8 -115 1500 <
ffff00007a7f2a00 3412364711 S Bi:1:006:8 -115 1500 <
ffff00007a7f2200 3412364740 S Bi:1:006:8 -115 1500 <
ffff00007a7f2000 3412364771 S Bi:1:006:8 -115 1500 <
ffff00007a7f2e00 3412364798 S Bi:1:006:8 -115 1500 <
ffff00007a7f2f00 3412364823 S Bi:1:006:8 -115 1500 <
ffff00007a7f2900 3412364911 S Bi:1:006:8 -115 1500 <
ffff000052e0bd00 3412364940 S Bi:1:006:8 -115 1500 <
ffff0000483bb700 3412364980 S Bi:1:006:8 -115 1500 <
ffff0000287f4e00 3412365020 S Bi:1:006:8 -115 1500 <
ffff0000287f4700 3412365056 S Bi:1:006:8 -115 1500 <
ffff0000bc79ed00 3412365090 S Bi:1:006:8 -115 1500 <
ffff00000ecb3d00 3412365117 S Bi:1:006:8 -115 1500 <
ffff00000ecb3600 3412365143 S Bi:1:006:8 -115 1500 <
ffff00000ecb3800 3412365169 S Bi:1:006:8 -115 1500 <
ffff00000e9dda00 3412365210 S Bi:1:006:8 -115 1500 <
ffff000052667c00 3412365238 S Bi:1:006:8 -115 1500 <
ffff000052495e00 3412365273 S Bi:1:006:8 -115 1500 <
ffff000052495800 3412365300 S Bi:1:006:8 -115 1500 <
ffff000052495700 3412365333 S Bi:1:006:8 -115 1500 <
ffff000052495300 3412365361 S Bi:1:006:8 -115 1500 <
ffff000052495400 3412365388 S Bi:1:006:8 -115 1500 <
ffff0000bc889f00 3412365419 S Bi:1:006:8 -115 1500 <
ffff00006c53e800 3412365462 S Bi:1:006:8 -115 1500 <
ffff0000bbb00a00 3412365518 S Bi:1:006:8 -115 1500 <
ffff0000bee65b00 3412365553 S Bi:1:006:8 -115 1500 <
ffff000044107b00 3412365587 S Bi:1:006:8 -115 1500 <
ffff000030dff800 3412365620 S Bi:1:006:8 -115 1500 <
ffff000022a72400 3412365659 S Bi:1:006:8 -115 1500 <
ffff000046f6a200 3412365702 S Bi:1:006:8 -115 1500 <
ffff000046f6a500 3412365744 S Bi:1:006:8 -115 1500 <
ffff000046f6a300 3412365773 S Bi:1:006:8 -115 1500 <
ffff000046f6a400 3412365802 S Bi:1:006:8 -115 1500 <
ffff000046f6ab00 3412365829 S Bi:1:006:8 -115 1500 <
ffff000046f6ad00 3412365863 S Bi:1:006:8 -115 1500 <
ffff00002472d300 3412365900 S Bi:1:006:8 -115 1500 <
ffff00002472de00 3412365926 S Bi:1:006:8 -115 1500 <
ffff000046f53700 3414449727 C Bi:1:006:8 -104 0
ffff000046f53c00 3414449896 C Bi:1:006:8 -104 0
ffff000046f53d00 3414449902 C Bi:1:006:8 -104 0
ffff000046f53a00 3414449909 C Bi:1:006:8 -104 0
ffff000047399200 3414449923 C Bi:1:006:8 -104 0
ffff000047399000 3414449927 C Bi:1:006:8 -104 0
ffff000047399100 3414449934 C Bi:1:006:8 -104 0
ffff000046f53100 3414449939 C Bi:1:006:8 -104 0
ffff0000bc7ef300 3414450253 C Bi:1:006:8 -104 0
ffff000055bfe900 3414450261 C Bi:1:006:8 -104 0
ffff000046e8a200 3414450267 C Bi:1:006:8 -104 0
ffff0000bc7ef200 3414450273 C Bi:1:006:8 -104 0
ffff000052e0b200 3414450499 C Bi:1:006:8 -104 0
ffff000052e0b000 3414450511 C Bi:1:006:8 -104 0
ffff000052e0bc00 3414450524 C Bi:1:006:8 -104 0
ffff000052e0bb00 3414450530 C Bi:1:006:8 -104 0
ffff000052e0be00 3414450538 C Bi:1:006:8 -104 0
ffff000052e0b800 3414450745 C Bi:1:006:8 -104 0
ffff00007a7f2d00 3414450755 C Bi:1:006:8 -104 0
ffff000052e0b500 3414450761 C Bi:1:006:8 -104 0
ffff00007a7f2300 3414451022 C Bi:1:006:8 -104 0
ffff00007a7f2400 3414451027 C Bi:1:006:8 -104 0
ffff00007a7f2c00 3414451033 C Bi:1:006:8 -104 0
ffff00007a7f2a00 3414451036 C Bi:1:006:8 -104 0
ffff00007a7f2200 3414451050 C Bi:1:006:8 -104 0
ffff00007a7f2000 3414451058 C Bi:1:006:8 -104 0
ffff00007a7f2100 3414451064 C Bi:1:006:8 -104 0
ffff00007a7f2f00 3414451262 C Bi:1:006:8 -104 0
ffff00007a7f2e00 3414451269 C Bi:1:006:8 -104 0
ffff000052e0bd00 3414451519 C Bi:1:006:8 -104 0
ffff0000483bb700 3414451526 C Bi:1:006:8 -104 0
ffff0000287f4e00 3414451531 C Bi:1:006:8 -104 0
ffff0000287f4700 3414451537 C Bi:1:006:8 -104 0
ffff0000bc79ed00 3414451545 C Bi:1:006:8 -104 0
ffff00007a7f2900 3414451552 C Bi:1:006:8 -104 0
ffff00000ecb3600 3414451742 C Bi:1:006:8 -104 0
ffff00000ecb3d00 3414451753 C Bi:1:006:8 -104 0
ffff00000e9dda00 3414452052 C Bi:1:006:8 -104 0
ffff000052667c00 3414452065 C Bi:1:006:8 -104 0
ffff000052495e00 3414452072 C Bi:1:006:8 -104 0
ffff000052495800 3414452078 C Bi:1:006:8 -104 0
ffff000052495700 3414452086 C Bi:1:006:8 -104 0
ffff000052495300 3414452093 C Bi:1:006:8 -104 0
ffff000052495400 3414452100 C Bi:1:006:8 -104 0
ffff00000ecb3800 3414452105 C Bi:1:006:8 -104 0
ffff00006c53e800 3414452402 C Bi:1:006:8 -104 0
ffff0000bc889f00 3414452418 C Bi:1:006:8 -104 0
ffff0000bee65b00 3414452631 C Bi:1:006:8 -104 0
ffff000044107b00 3414452640 C Bi:1:006:8 -104 0
ffff0000bbb00a00 3414452648 C Bi:1:006:8 -104 0
ffff000022a72400 3414452902 C Bi:1:006:8 -104 0
ffff000046f6a200 3414452911 C Bi:1:006:8 -104 0
ffff000046f6a500 3414452918 C Bi:1:006:8 -104 0
ffff000030dff800 3414452925 C Bi:1:006:8 -104 0
ffff000046f6a400 3414453134 C Bi:1:006:8 -104 0
ffff000046f6ab00 3414453148 C Bi:1:006:8 -104 0
ffff000046f6a300 3414453154 C Bi:1:006:8 -104 0
ffff00002472d300 3414453436 C Bi:1:006:8 -104 0
ffff00002472de00 3414453443 C Bi:1:006:8 -104 0
ffff000046f6ad00 3414453452 C Bi:1:006:8 -104 0
ffff0000bbe51d00 3414454606 C Ii:1:006:7 -2:16 0
ffff00004834fc00 3414455737 C Bi:1:006:4 -2 0
ffff0000bc5e0200 3414456688 C Bi:1:006:4 -2 0
ffff0000bc5e0300 3414456896 C Bi:1:006:4 -2 0
ffff0000bc5e0400 3414457772 C Bi:1:006:4 -2 0
ffff00004834f500 3414458677 C Ii:1:006:3 -2:16 0
ffff000031511f00 3414459626 C Bi:1:006:2 -2 0
ffff000031511200 3414459845 C Bi:1:006:2 -2 0
ffff000031511b00 3414460031 C Bi:1:006:2 -2 0
ffff000031511d00 3414460924 C Bi:1:006:2 -2 0
ffff00001fd2df00 3414461909 C Bi:1:006:1 -2 0
ffff00001fd2d000 3414462085 C Bi:1:006:1 -2 0
ffff00000e904100 3414463049 C Bi:1:006:1 -2 0
ffff000014838000 3414463216 C Bi:1:006:1 -2 0
ffff00000bc3c300 3414463353 S Co:1:006:0 s 00 03 0001 0000 0000 0
ffff00000bc3c300 3414463654 C Co:1:006:0 0 0
ffff00000bc3c300 3414463709 S Co:1:002:0 s 23 03 0002 0002 0000 0
ffff00000bc3c300 3414463795 C Co:1:002:0 0 0
ffff0000befcda00 3414485333 C Ii:1:002:1 -2:2048 0
ffff00000bc3c300 3414485443 S Co:1:002:0 s 00 03 0001 0000 0000 0
ffff00000bc3c300 3414485535 C Co:1:002:0 0 0
ffff00000bc3c300 3414485563 S Co:1:001:0 s 23 03 0002 0001 0000 0
ffff00000bc3c300 3414504874 C Co:1:001:0 0 0
ffff0000bf035e00 3414548807 C Ii:1:001:1 0:2048 1 = 02
ffff0000bf035e00 3414548937 S Ii:1:001:1 -115:2048 4 <
ffff0000bc5a0600 3414549188 S Ci:1:001:0 s a3 00 0000 0001 0004 4 <
ffff0000bc5a0600 3414550125 C Ci:1:001:0 0 4 = 03050400
ffff0000bc5a0600 3414550224 S Co:1:001:0 s 23 01 0012 0001 0000 0
ffff0000bc5a0600 3414550253 C Co:1:001:0 0 0
ffff0000bc5a0600 3414572257 S Ci:1:001:0 s a3 00 0000 0001 0004 4 <
ffff0000bc5a0600 3414572363 C Ci:1:001:0 0 4 = 03050000
ffff0000bc5a0600 3414592209 S Ci:1:002:0 s 80 00 0000 0000 0002 2 <
ffff0000bc5a0600 3414593195 C Ci:1:002:0 0 2 = 0300
ffff0000bc5a0600 3414593249 S Co:1:002:0 s 00 01 0001 0000 0000 0
ffff0000bc5a0600 3414594022 C Co:1:002:0 0 0
ffff0000bc5a0600 3414594134 S Ci:1:002:0 s a3 00 0000 0001 0004 4 <
ffff0000bc5a0600 3414594854 C Ci:1:002:0 0 4 = 07050000
ffff0000bc5a0600 3414594917 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff0000bc5a0600 3414595674 C Ci:1:002:0 0 4 = 01010500
ffff0000bc5a0600 3414595723 S Co:1:002:0 s 23 01 0010 0002 0000 0
ffff0000bc5a0600 3414596471 C Co:1:002:0 0 0
ffff0000bc5a0600 3414596885 S Ci:1:002:0 s a3 00 0000 0003 0004 4 <
ffff0000bc5a0600 3414597661 C Ci:1:002:0 0 4 = 00010000
ffff0000befcda00 3414704815 S Ii:1:002:1 -115:2048 1 <
ffff0000bc5a0600 3414705456 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff0000bc5a0600 3414705668 C Ci:1:002:0 0 4 = 01010500
ffff0000bc5a0600 3414705706 S Co:1:002:0 s 23 01 0010 0002 0000 0
ffff0000bc5a0600 3414705781 C Co:1:002:0 0 0
ffff0000bc5a0600 3414705810 S Co:1:002:0 s 23 01 0012 0002 0000 0
ffff0000bc5a0600 3414705876 C Co:1:002:0 0 0
ffff0000bc5a0600 3414728273 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff0000bc5a0600 3414729045 C Ci:1:002:0 0 4 = 01010000
ffff0000bc5a0600 3414749623 S Co:1:002:0 s 23 03 0004 0002 0000 0
ffff0000bc5a0600 3414750388 C Co:1:002:0 0 0
ffff0000bc5a0600 3414772782 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff0000bc5a0600 3414773561 C Ci:1:002:0 0 4 = 03051000
ffff0000bc5a0600 3414773606 S Co:1:002:0 s 23 01 0014 0002 0000 0
ffff0000bc5a0600 3414773677 C Co:1:002:0 0 0
ffff0000bc5a0600 3414857343 S Ci:1:000:0 s 80 06 0100 0000 0040 64 <
ffff0000bc5a0600 3414857813 C Ci:1:000:0 0 18 = 12010002 00000040 20206020 00000302 0401
ffff0000bc5a0600 3414857922 S Co:1:002:0 s 23 03 0004 0002 0000 0
ffff0000bc5a0600 3414858015 C Co:1:002:0 0 0
ffff0000bc5a0600 3414876395 S Ci:1:002:0 s a3 00 0000 0002 0004 4 <
ffff0000bc5a0600 3414877371 C Ci:1:002:0 0 4 = 03051000
ffff0000bc5a0600 3414878332 S Co:1:002:0 s 23 01 0014 0002 0000 0
ffff0000bc5a0600 3414878450 C Co:1:002:0 0 0
ffff0000bc5a0600 3414956790 S Ci:1:006:0 s 80 06 0100 0000 0012 18 <
ffff0000bc5a0600 3414957867 C Ci:1:006:0 0 18 = 12010002 00000040 20206020 00000302 0401
ffff0000bc5a0300 3414958120 S Ci:1:006:0 s 80 06 0200 0000 0091 145 <
ffff0000bc5a0300 3414959137 C Ci:1:006:0 0 145 = 09029100 050101e0 fa090400 0002ffff ff000705 81020002 00070501 02000200
ffff0000bc5a0600 3414983088 S Co:1:006:0 s 00 09 0001 0000 0000 0
ffff0000bc5a0600 3414984395 C Co:1:006:0 0 0
ffff0000bc5a0600 3414988497 S Ci:1:006:0 s 80 00 0000 0000 0002 2 <
ffff0000bc5a0600 3414988847 C Ci:1:006:0 0 2 = 0000
ffff0000bbe51d00 3414989618 S Ii:1:006:7 -115:16 64 <
ffff0000bc5a0600 3414989746 S Bi:1:006:8 -115 1500 <
ffff0000bc5a0300 3414989778 S Bi:1:006:8 -115 1500 <
ffff0000bc5a0200 3414989807 S Bi:1:006:8 -115 1500 <
ffff0000bc5a0400 3414989835 S Bi:1:006:8 -115 1500 <
ffff0000481b8c00 3414989867 S Bi:1:006:8 -115 1500 <
ffff0000481b8a00 3414989891 S Bi:1:006:8 -115 1500 <
ffff0000481b8400 3414989915 S Bi:1:006:8 -115 1500 <
ffff0000481b8300 3414989935 S Bi:1:006:8 -115 1500 <
ffff0000481b8d00 3414989959 S Bi:1:006:8 -115 1500 <
ffff0000481b8900 3414989984 S Bi:1:006:8 -115 1500 <

Re: USB device disconnects on resume

[Alan Stern]

On Mon, Apr 25, 2022 at 11:45:05AM +0200, Martin Kepplinger wrote:
> Alan, thanks so much for asking these questions and thinking this
> through! It helps.
> 
> Am Donnerstag, dem 21.04.2022 um 10:24 -0400 schrieb Alan Stern:
> > On Thu, Apr 21, 2022 at 12:38:56PM +0200, Martin Kepplinger wrote:
> > > Am Mittwoch, dem 20.04.2022 um 10:40 -0400 schrieb Alan Stern:
> > > > On Wed, Apr 20, 2022 at 12:37:36PM +0200, Martin Kepplinger
> > > > wrote:
> > > > > Resetting itself doesn't usually fail in the sense that a
> > > > > device
> > > > > would
> > > > > not work anymore after resetting. The problem is that the
> > > > > resets
> > > > > happen
> > > > > in the first place. 90+% of runtime-resumes are fine - auto-
> > > > > and
> > > > > wakeup-resume. Resetting is a major problem though, imagine a
> > > > > modem
> > > > > device being re-enumerated during a phone call or "realtime"
> > > > > data
> > > > > connection. I see that a lot.
> > > > 
> > > > Okay, I see.
> > 
> > By the way, I assume that while resetting the modem is a major
> > problem 
> > for your potential use cases, having it crash with no hope of
> > recovery 
> > is even worse.  But maybe I'm wrong...
> 
> Sure that's true (and I have other usb-related problems too that result
> in the xhci HC dying even, when I see "xhci-hcd.4.auto: Port resume
> timed out, port 1-1: 0xfe3", so the Hub where the modem is connected)
> but these resets are a seperate issue I want to tackle now and see
> whether it help with other usb-related problems, so let's focus on this
> disconnect/reset situation. So let's not get confused :)

Okay.

> > > > > 1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for
> > > > > CONNECT
> > > > > 1650447001.324925 pureos kernel: usb 1-1.2: finish resume
> > > > > 1650447003.831095 pureos kernel: usb 1-1.2: usb auto-suspend,
> > > > > wakeup 1
> > > > > 1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
> > > > > 1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend,
> > > > > wakeup
> > > > > 1
> > > > > 1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume
> > > > 
> > > > This wakeup occurred only 48 ms after the hub was runtime
> > > > suspended. 
> > > > But here at least the cause is evident: The hub sent a wakeup
> > > > request
> > > > because its child (the 1-1.2 modem) disconnected.
> > > 
> > > fwiw, that wakeup-resume *always* comes about 50 ms after the last
> > > runtime suspend.
> > 
> > Maybe the modem's firmware has some 50-ms timeout that expires and
> > then 
> > causes the crash.
> 
> I now recorded usbmon (1u) traffic of a similar sequence I sent here,
> with a few usbmon-timestamps in the logs:
> 
> https://source.puri.sm/Librem5/linux/-/issues/303#note_197913
> 
> the usbmon log textfile is attached in that comment link and in this
> email.

Hmmm.  The usbmon trace appears to show a successful reset-resume.  Did
anything bad happen during that experiment from your point of view?

> > > > > 1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for
> > > > > CONNECT
> > > > > 1650447003.945755 pureos kernel: usb 1-1: finish resume
> > > > > 1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
> > > > > 1650447003.949226 pureos kernel: usb 1-1-port1: status 0507
> > > > > change
> > > > > 0000
> > > > > 1650447003.949430 pureos kernel: usb 1-1-port2: status 0101
> > > > > change
> > > > > 0005
> > > > > 1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports 3
> > > > > chg
> > > > > 0004
> > > > > evt 0000
> > > > > 1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-resume
> > > > > 1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for
> > > > > CONNECT
> > > > > 1650447004.097255 pureos kernel: usb 1-1.2: finish reset-resume
> > > > > 1650447004.182333 pureos kernel: usb 1-1.2: reset high-speed
> > > > > USB
> > > > > device
> > > > > number 5 using xhci-hcd
> > > > > 1650447004.314425 pureos kernel: usb 1-1-port2: resume, status
> > > > > 0
> > > > > 1650447004.317628 pureos kernel: usb 1-1-port2: status 0101,
> > > > > change
> > > > > 0004, 12 Mb/s

This line indicates the real source of the trouble.  Shortly after the 
reset part of the reset-resume, the modem disconnected again.  That is, 
it disconnected itself twice: Once while it was suspended or right when 
the resume occurred, and then a second time immediately following the 
reset.

> > > > > 1650447004.323374 pureos kernel: usb 1-1.2: unregistering
> > > > > device
> > > > 
> > > > And it looks like in this case, the reset-resume failed.
> > > 
> > > Well, at least reset_resume has been set, which I want to avoid.
> > 
> > Do you mean you would prefer to have the modem disconnect permanently
> > (or at least until the next reboot)?
> 
> no. I mean I'd prefer the kernel keep the device usable when such a
> disconnect happens - after a short pause until the modem is up again -
> and not re-enumerate.

That's exactly what a reset-resume is supposed to do.  Maybe the pause 
is too short; you can increase it by adding an msleep() call in 
finish_port_resume() just before it calls usb_reset_and_verify_device().

> An audio stream is not being interrupted by such a usb disconnect and
> if I'd keep the ttyUSB device for userspace, I'd keep an opened ttyUSB
> controllable - even if possibly with a large latency spike. That would
> stay a bad workaround of course. Do you know what I'm thinking about?

Certainly.

> > One thing you can do pretty easily, without changing the kernel, is 
> > prevent the modem from going into runtime suspend in the first
> > place.  
> > For example, if you have a program like powertop overseeing your
> > runtime 
> > power management, you could tell it not to let the modem suspend.  Or
> > if 
> > you want to set it up by hand, the command is:
> > 
> >         echo on >/sys/bus/usb/devices/.../power/control
> > 
> > (where "..." is the appropriate path for the modem device, such as 
> > "1-1.2").  You can even write a udev script to do this automatically 
> > whenever the modem is detected.
> 
> I know that this "solves" my problems but that also prevents the usb2
> hub (1-1) from suspending and that's not a practical solution. The hub
> uses a *lot* of power.

And there's no way to use a different hub -- one that consumes less 
power -- because the connections are hard-wired on the board.  :-(

> > > In theory, if I know this behaviour in advance, I think I should be
> > > able to somehow wait until the device is ready again instead of
> > > resetting.
> > 
> > What if the modem never becomes ready again (or not until you
> > reboot)?  
> > I think that sort of behavior is not at all unlikely.  You can test
> > this 
> > by disabling the code in finish_port_resume() that does reset-
> > resumes.
> 
> if I just do that, I get "gone after usb resume? status -5" and thus a
> reset is triggered after all (also, when I do msleep(500) instead of
> reset_and_verify_device() there).

Here's a quick low-level description of what's going on.

When a hub gets a disconnect event on one of its ports, it disables the 
port.  The port then remains disabled, even if another device is plugged 
in, until a successful port reset occurs.  In other words, the _only_ 
way to re-enable a port is to issue a reset.

The reset-resume mechanism in the kernel takes care of issuing the 
reset, and it checks to make sure that the device attached to the port 
hasn't been changed (i.e., it's still the same device as before, not a 
new one).  If that works, the device is put back in its former operating 
state and should keep on functioning normally.  If that doesn't work, or 
if there is a new device attached to the port, the kernel treats the 
event just like a normal disconnect + connect.

So what you want really _is_ a reset-resume.  If successful, it will 
give the behavior you mentioned above: continued transmission with maybe 
some data loss and a big latency spike at one point.  Anything other 
than a successful reset-resume will cause the ttyUSB file to become 
unusable, exactly what you don't want.

So the real question you need to answer is why a reset-resume sometimes 
fails with this modem.  I suspect the answer will be that the modem is 
buggy, and there may not be any way to work around the bug.  But try 
putting the msleep(500) just before the usb_reset_and_verify_device() 
call; maybe it will help.

Alan Stern

Re: USB device disconnects on resume

[Martin Kepplinger]

Am Dienstag, dem 26.04.2022 um 10:58 -0400 schrieb Alan Stern:
> On Mon, Apr 25, 2022 at 11:45:05AM +0200, Martin Kepplinger wrote:
> > Alan, thanks so much for asking these questions and thinking this
> > through! It helps.
> > 
> > Am Donnerstag, dem 21.04.2022 um 10:24 -0400 schrieb Alan Stern:
> > > On Thu, Apr 21, 2022 at 12:38:56PM +0200, Martin Kepplinger
> > > wrote:
> > > > Am Mittwoch, dem 20.04.2022 um 10:40 -0400 schrieb Alan Stern:
> > > > > On Wed, Apr 20, 2022 at 12:37:36PM +0200, Martin Kepplinger
> > > > > wrote:
> > > > > > Resetting itself doesn't usually fail in the sense that a
> > > > > > device
> > > > > > would
> > > > > > not work anymore after resetting. The problem is that the
> > > > > > resets
> > > > > > happen
> > > > > > in the first place. 90+% of runtime-resumes are fine -
> > > > > > auto-
> > > > > > and
> > > > > > wakeup-resume. Resetting is a major problem though, imagine
> > > > > > a
> > > > > > modem
> > > > > > device being re-enumerated during a phone call or
> > > > > > "realtime"
> > > > > > data
> > > > > > connection. I see that a lot.
> > > > > 
> > > > > Okay, I see.
> > > 
> > > By the way, I assume that while resetting the modem is a major
> > > problem 
> > > for your potential use cases, having it crash with no hope of
> > > recovery 
> > > is even worse.  But maybe I'm wrong...
> > 
> > Sure that's true (and I have other usb-related problems too that
> > result
> > in the xhci HC dying even, when I see "xhci-hcd.4.auto: Port resume
> > timed out, port 1-1: 0xfe3", so the Hub where the modem is
> > connected)
> > but these resets are a seperate issue I want to tackle now and see
> > whether it help with other usb-related problems, so let's focus on
> > this
> > disconnect/reset situation. So let's not get confused :)
> 
> Okay.
> 
> > > > > > 1650447001.318845 pureos kernel: usb 1-1.2: Waited 0ms for
> > > > > > CONNECT
> > > > > > 1650447001.324925 pureos kernel: usb 1-1.2: finish resume
> > > > > > 1650447003.831095 pureos kernel: usb 1-1.2: usb auto-
> > > > > > suspend,
> > > > > > wakeup 1
> > > > > > 1650447003.854701 pureos kernel: hub 1-1:1.0: hub_suspend
> > > > > > 1650447003.874773 pureos kernel: usb 1-1: usb auto-suspend,
> > > > > > wakeup
> > > > > > 1
> > > > > > 1650447003.922054 pureos kernel: usb 1-1: usb wakeup-resume
> > > > > 
> > > > > This wakeup occurred only 48 ms after the hub was runtime
> > > > > suspended. 
> > > > > But here at least the cause is evident: The hub sent a wakeup
> > > > > request
> > > > > because its child (the 1-1.2 modem) disconnected.
> > > > 
> > > > fwiw, that wakeup-resume *always* comes about 50 ms after the
> > > > last
> > > > runtime suspend.
> > > 
> > > Maybe the modem's firmware has some 50-ms timeout that expires
> > > and
> > > then 
> > > causes the crash.
> > 
> > I now recorded usbmon (1u) traffic of a similar sequence I sent
> > here,
> > with a few usbmon-timestamps in the logs:
> > 
> > https://source.puri.sm/Librem5/linux/-/issues/303#note_197913
> > 
> > the usbmon log textfile is attached in that comment link and in
> > this
> > email.
> 
> Hmmm.  The usbmon trace appears to show a successful reset-resume. 
> Did
> anything bad happen during that experiment from your point of view?

well, the modem device got disconnected and re-enumerated.

> 
> > > > > > 1650447003.942066 pureos kernel: usb 1-1: Waited 0ms for
> > > > > > CONNECT
> > > > > > 1650447003.945755 pureos kernel: usb 1-1: finish resume
> > > > > > 1650447003.947589 pureos kernel: hub 1-1:1.0: hub_resume
> > > > > > 1650447003.949226 pureos kernel: usb 1-1-port1: status 0507
> > > > > > change
> > > > > > 0000
> > > > > > 1650447003.949430 pureos kernel: usb 1-1-port2: status 0101
> > > > > > change
> > > > > > 0005
> > > > > > 1650447004.058779 pureos kernel: hub 1-1:1.0: state 7 ports
> > > > > > 3
> > > > > > chg
> > > > > > 0004
> > > > > > evt 0000
> > > > > > 1650447004.074089 pureos kernel: usb 1-1.2: usb wakeup-
> > > > > > resume
> > > > > > 1650447004.094056 pureos kernel: usb 1-1.2: Waited 0ms for
> > > > > > CONNECT
> > > > > > 1650447004.097255 pureos kernel: usb 1-1.2: finish reset-
> > > > > > resume
> > > > > > 1650447004.182333 pureos kernel: usb 1-1.2: reset high-
> > > > > > speed
> > > > > > USB
> > > > > > device
> > > > > > number 5 using xhci-hcd
> > > > > > 1650447004.314425 pureos kernel: usb 1-1-port2: resume,
> > > > > > status
> > > > > > 0
> > > > > > 1650447004.317628 pureos kernel: usb 1-1-port2: status
> > > > > > 0101,
> > > > > > change
> > > > > > 0004, 12 Mb/s
> 
> This line indicates the real source of the trouble.  Shortly after
> the 
> reset part of the reset-resume, the modem disconnected again.  That
> is, 
> it disconnected itself twice: Once while it was suspended or right
> when 
> the resume occurred, and then a second time immediately following the
> reset.

indeed...

> 
> > > > > > 1650447004.323374 pureos kernel: usb 1-1.2: unregistering
> > > > > > device
> > > > > 
> > > > > And it looks like in this case, the reset-resume failed.
> > > > 
> > > > Well, at least reset_resume has been set, which I want to
> > > > avoid.
> > > 
> > > Do you mean you would prefer to have the modem disconnect
> > > permanently
> > > (or at least until the next reboot)?
> > 
> > no. I mean I'd prefer the kernel keep the device usable when such a
> > disconnect happens - after a short pause until the modem is up
> > again -
> > and not re-enumerate.
> 
> That's exactly what a reset-resume is supposed to do.  Maybe the
> pause 
> is too short; you can increase it by adding an msleep() call in 
> finish_port_resume() just before it calls
> usb_reset_and_verify_device().
> 
> > An audio stream is not being interrupted by such a usb disconnect
> > and
> > if I'd keep the ttyUSB device for userspace, I'd keep an opened
> > ttyUSB
> > controllable - even if possibly with a large latency spike. That
> > would
> > stay a bad workaround of course. Do you know what I'm thinking
> > about?
> 
> Certainly.
> 
> > > One thing you can do pretty easily, without changing the kernel,
> > > is 
> > > prevent the modem from going into runtime suspend in the first
> > > place.  
> > > For example, if you have a program like powertop overseeing your
> > > runtime 
> > > power management, you could tell it not to let the modem
> > > suspend.  Or
> > > if 
> > > you want to set it up by hand, the command is:
> > > 
> > >         echo on >/sys/bus/usb/devices/.../power/control
> > > 
> > > (where "..." is the appropriate path for the modem device, such
> > > as 
> > > "1-1.2").  You can even write a udev script to do this
> > > automatically 
> > > whenever the modem is detected.
> > 
> > I know that this "solves" my problems but that also prevents the
> > usb2
> > hub (1-1) from suspending and that's not a practical solution. The
> > hub
> > uses a *lot* of power.
> 
> And there's no way to use a different hub -- one that consumes less 
> power -- because the connections are hard-wired on the board.  :-(

correct.

> 
> > > > In theory, if I know this behaviour in advance, I think I
> > > > should be
> > > > able to somehow wait until the device is ready again instead of
> > > > resetting.
> > > 
> > > What if the modem never becomes ready again (or not until you
> > > reboot)?  
> > > I think that sort of behavior is not at all unlikely.  You can
> > > test
> > > this 
> > > by disabling the code in finish_port_resume() that does reset-
> > > resumes.
> > 
> > if I just do that, I get "gone after usb resume? status -5" and
> > thus a
> > reset is triggered after all (also, when I do msleep(500) instead
> > of
> > reset_and_verify_device() there).
> 
> Here's a quick low-level description of what's going on.
> 
> When a hub gets a disconnect event on one of its ports, it disables
> the 
> port.  The port then remains disabled, even if another device is
> plugged 
> in, until a successful port reset occurs.  In other words, the _only_
> way to re-enable a port is to issue a reset.
> 
> The reset-resume mechanism in the kernel takes care of issuing the 
> reset, and it checks to make sure that the device attached to the
> port 
> hasn't been changed (i.e., it's still the same device as before, not
> a 
> new one).  If that works, the device is put back in its former
> operating 
> state and should keep on functioning normally.  If that doesn't work,
> or 
> if there is a new device attached to the port, the kernel treats the 
> event just like a normal disconnect + connect.
> 
> So what you want really _is_ a reset-resume.  If successful, it will 
> give the behavior you mentioned above: continued transmission with
> maybe 
> some data loss and a big latency spike at one point.  Anything other 
> than a successful reset-resume will cause the ttyUSB file to become 
> unusable, exactly what you don't want.
> 
> So the real question you need to answer is why a reset-resume
> sometimes 
> fails with this modem.  I suspect the answer will be that the modem
> is 
> buggy, and there may not be any way to work around the bug.  But try 
> putting the msleep(500) just before the usb_reset_and_verify_device()
> call; maybe it will help.
> 
> Alan Stern

ok. thanks a lot for that suggestion! I added an extremely long
msleep(5000) there and the behaviour indeed consistently changes a bit.
(almost consistently, rarely I see the modem coming up as low-speed
device, which is not allowed by hub.c and thus re-enumeration is
triggered) but I added more debug messages and almost always that's how
it looks like. I hope my added messages are understandable enough:

11:43:50.800648: hub 1-1:1.0: hub_suspend
11:43:50.820074: usb 1-1: usb auto-suspend, wakeup 1
11:43:50.880637: usb 1-1: usb wakeup-resume
11:43:50.908646: usb 1-1: Waited 0ms for CONNECT
11:43:50.910445: usb 1-1: finish resume
11:43:50.911865: hub 1-1:1.0: hub_resume
11:43:50.913842: usb 1-1-port1: status 0507 change 0000
11:43:50.914026: usb 1-1-port2: status 0101 change 0005
11:43:51.020887: usb usb1-port1: resume, status 0
11:43:51.021205: hub 1-1:1.0: state 7 ports 3 chg 0004 evt 0000
11:43:51.048658: usb 1-1.2: usb wakeup-resume
11:43:51.076670: usb 1-1.2: Waited 0ms for CONNECT
11:43:51.078573: usb 1-1.2: finish reset-resume
11:43:56.305074: usb 1-1-port2: hub_port_reset: starting try 0 of 5
11:43:56.328683: hub 1-1:1.0: port_wait_reset: err = -11
11:43:56.333794: usb 1-1-port2: not enabled, trying reset again... 0 of
5. status=-11
11:43:56.334074: usb 1-1-port2: hub_port_reset: starting try 1 of 5
11:43:56.536645: usb 1-1-port2: hub_port_reset: no superspeed. status:
0. bail out
11:43:56.628824: usb 1-1.2: reset high-speed USB device number 6 using
xhci-hcd
11:43:56.640305: usb 1-1-port2: hub_port_reset: starting try 0 of 5
11:43:56.656735: usb 1-1-port2: hub_port_reset: no superspeed. status:
0. bail out
11:43:56.752738: usb 1-1-port2: resume, status 0
11:43:56.755442: usb 1-1-port2: port_event: call
hub_port_connect_change because connect_change is 1
11:43:56.756663: usb 1-1-port2: status 0101, change 0004, 12 Mb/s
11:43:56.756942: usb 1-1.2: hub_port_connect_change: not resuscitating.
11:43:56.762495: usb 1-1-port2: hub_port_connect_change: could not
revalidate the connection. call hub_port_connect.
11:43:56.762797: usb 1-1.2: USB disconnect, device number 6
11:43:56.765481: usb 1-1.2: unregistering device

I'm sending this before analyzing it further. I'll do so soon but
wanted to show you that already.

                            martin

Re: USB device disconnects on resume

[Alan Stern]

On Thu, Apr 28, 2022 at 09:01:50AM +0200, Martin Kepplinger wrote:
> Am Dienstag, dem 26.04.2022 um 10:58 -0400 schrieb Alan Stern:
> > Here's a quick low-level description of what's going on.
> > 
> > When a hub gets a disconnect event on one of its ports, it disables
> > the 
> > port.  The port then remains disabled, even if another device is
> > plugged 
> > in, until a successful port reset occurs.  In other words, the _only_
> > way to re-enable a port is to issue a reset.
> > 
> > The reset-resume mechanism in the kernel takes care of issuing the 
> > reset, and it checks to make sure that the device attached to the
> > port 
> > hasn't been changed (i.e., it's still the same device as before, not
> > a 
> > new one).  If that works, the device is put back in its former
> > operating 
> > state and should keep on functioning normally.  If that doesn't work,
> > or 
> > if there is a new device attached to the port, the kernel treats the 
> > event just like a normal disconnect + connect.
> > 
> > So what you want really _is_ a reset-resume.  If successful, it will 
> > give the behavior you mentioned above: continued transmission with
> > maybe 
> > some data loss and a big latency spike at one point.  Anything other 
> > than a successful reset-resume will cause the ttyUSB file to become 
> > unusable, exactly what you don't want.
> > 
> > So the real question you need to answer is why a reset-resume
> > sometimes 
> > fails with this modem.  I suspect the answer will be that the modem
> > is 
> > buggy, and there may not be any way to work around the bug.  But try 
> > putting the msleep(500) just before the usb_reset_and_verify_device()
> > call; maybe it will help.
> > 
> > Alan Stern
> 
> ok. thanks a lot for that suggestion! I added an extremely long
> msleep(5000) there and the behaviour indeed consistently changes a bit.
> (almost consistently, rarely I see the modem coming up as low-speed
> device, which is not allowed by hub.c and thus re-enumeration is
> triggered) but I added more debug messages and almost always that's how
> it looks like. I hope my added messages are understandable enough:
> 
> 11:43:50.800648: hub 1-1:1.0: hub_suspend
> 11:43:50.820074: usb 1-1: usb auto-suspend, wakeup 1
> 11:43:50.880637: usb 1-1: usb wakeup-resume
> 11:43:50.908646: usb 1-1: Waited 0ms for CONNECT
> 11:43:50.910445: usb 1-1: finish resume
> 11:43:50.911865: hub 1-1:1.0: hub_resume
> 11:43:50.913842: usb 1-1-port1: status 0507 change 0000
> 11:43:50.914026: usb 1-1-port2: status 0101 change 0005
> 11:43:51.020887: usb usb1-port1: resume, status 0
> 11:43:51.021205: hub 1-1:1.0: state 7 ports 3 chg 0004 evt 0000
> 11:43:51.048658: usb 1-1.2: usb wakeup-resume
> 11:43:51.076670: usb 1-1.2: Waited 0ms for CONNECT
> 11:43:51.078573: usb 1-1.2: finish reset-resume
> 11:43:56.305074: usb 1-1-port2: hub_port_reset: starting try 0 of 5
> 11:43:56.328683: hub 1-1:1.0: port_wait_reset: err = -11

-EAGAIN means that the modem disconnected around the time of the reset, 
so the reset failed.

> 11:43:56.333794: usb 1-1-port2: not enabled, trying reset again... 0 of
> 5. status=-11
> 11:43:56.334074: usb 1-1-port2: hub_port_reset: starting try 1 of 5
> 11:43:56.536645: usb 1-1-port2: hub_port_reset: no superspeed. status:
> 0. bail out

Not sure what that means.

> 11:43:56.628824: usb 1-1.2: reset high-speed USB device number 6 using
> xhci-hcd
> 11:43:56.640305: usb 1-1-port2: hub_port_reset: starting try 0 of 5
> 11:43:56.656735: usb 1-1-port2: hub_port_reset: no superspeed. status:
> 0. bail out
> 11:43:56.752738: usb 1-1-port2: resume, status 0

And it's hard to tell exactly what that refers to.

> 11:43:56.755442: usb 1-1-port2: port_event: call
> hub_port_connect_change because connect_change is 1
> 11:43:56.756663: usb 1-1-port2: status 0101, change 0004, 12 Mb/s
> 11:43:56.756942: usb 1-1.2: hub_port_connect_change: not resuscitating.
> 11:43:56.762495: usb 1-1-port2: hub_port_connect_change: could not
> revalidate the connection. call hub_port_connect.
> 11:43:56.762797: usb 1-1.2: USB disconnect, device number 6
> 11:43:56.765481: usb 1-1.2: unregistering device

It looks like these things happened after the reset-resume failed.  But 
the control flow isn't clear (more log messages might help).

> I'm sending this before analyzing it further. I'll do so soon but
> wanted to show you that already.

Okay.  But it seems that the modem refused to be reset properly.  When 
that happens there's no way to avoid disconnection.  And in fact I would 
expect that re-initialization and enumeration would then be impossible, 
since the first step of initialization is to perform a reset.

Alan Stern

Re: USB device disconnects on resume

[Martin Kepplinger]

Am Donnerstag, dem 28.04.2022 um 15:13 -0400 schrieb Alan Stern:
> On Thu, Apr 28, 2022 at 09:01:50AM +0200, Martin Kepplinger wrote:
> > Am Dienstag, dem 26.04.2022 um 10:58 -0400 schrieb Alan Stern:
> > > Here's a quick low-level description of what's going on.
> > > 
> > > When a hub gets a disconnect event on one of its ports, it
> > > disables
> > > the 
> > > port.  The port then remains disabled, even if another device is
> > > plugged 
> > > in, until a successful port reset occurs.  In other words, the
> > > _only_
> > > way to re-enable a port is to issue a reset.
> > > 
> > > The reset-resume mechanism in the kernel takes care of issuing
> > > the 
> > > reset, and it checks to make sure that the device attached to the
> > > port 
> > > hasn't been changed (i.e., it's still the same device as before,
> > > not
> > > a 
> > > new one).  If that works, the device is put back in its former
> > > operating 
> > > state and should keep on functioning normally.  If that doesn't
> > > work,
> > > or 
> > > if there is a new device attached to the port, the kernel treats
> > > the 
> > > event just like a normal disconnect + connect.
> > > 
> > > So what you want really _is_ a reset-resume.  If successful, it
> > > will 
> > > give the behavior you mentioned above: continued transmission
> > > with
> > > maybe 
> > > some data loss and a big latency spike at one point.  Anything
> > > other 
> > > than a successful reset-resume will cause the ttyUSB file to
> > > become 
> > > unusable, exactly what you don't want.
> > > 
> > > So the real question you need to answer is why a reset-resume
> > > sometimes 
> > > fails with this modem.  I suspect the answer will be that the
> > > modem
> > > is 
> > > buggy, and there may not be any way to work around the bug.  But
> > > try 
> > > putting the msleep(500) just before the
> > > usb_reset_and_verify_device()
> > > call; maybe it will help.
> > > 
> > > Alan Stern
> > 
> > ok. thanks a lot for that suggestion! I added an extremely long
> > msleep(5000) there and the behaviour indeed consistently changes a
> > bit.
> > (almost consistently, rarely I see the modem coming up as low-speed
> > device, which is not allowed by hub.c and thus re-enumeration is
> > triggered) but I added more debug messages and almost always that's
> > how
> > it looks like. I hope my added messages are understandable enough:
> > 
> > 11:43:50.800648: hub 1-1:1.0: hub_suspend
> > 11:43:50.820074: usb 1-1: usb auto-suspend, wakeup 1
> > 11:43:50.880637: usb 1-1: usb wakeup-resume
> > 11:43:50.908646: usb 1-1: Waited 0ms for CONNECT
> > 11:43:50.910445: usb 1-1: finish resume
> > 11:43:50.911865: hub 1-1:1.0: hub_resume
> > 11:43:50.913842: usb 1-1-port1: status 0507 change 0000
> > 11:43:50.914026: usb 1-1-port2: status 0101 change 0005
> > 11:43:51.020887: usb usb1-port1: resume, status 0
> > 11:43:51.021205: hub 1-1:1.0: state 7 ports 3 chg 0004 evt 0000
> > 11:43:51.048658: usb 1-1.2: usb wakeup-resume
> > 11:43:51.076670: usb 1-1.2: Waited 0ms for CONNECT
> > 11:43:51.078573: usb 1-1.2: finish reset-resume
> > 11:43:56.305074: usb 1-1-port2: hub_port_reset: starting try 0 of 5
> > 11:43:56.328683: hub 1-1:1.0: port_wait_reset: err = -11
> 
> -EAGAIN means that the modem disconnected around the time of the
> reset, 
> so the reset failed.
> 

ok, but we try up to 5 times and the second time below runs further,
until the !hub_is_superspeed()

> > 11:43:56.333794: usb 1-1-port2: not enabled, trying reset again...
> > 0 of
> > 5. status=-11
> > 11:43:56.334074: usb 1-1-port2: hub_port_reset: starting try 1 of 5
> > 11:43:56.536645: usb 1-1-port2: hub_port_reset: no superspeed.
> > status:
> > 0. bail out
> 
> Not sure what that means.

https://elixir.bootlin.com/linux/v5.18-rc4/source/drivers/usb/core/hub.c#L2995

> 
> > 11:43:56.628824: usb 1-1.2: reset high-speed USB device number 6
> > using
> > xhci-hcd
> > 11:43:56.640305: usb 1-1-port2: hub_port_reset: starting try 0 of 5
> > 11:43:56.656735: usb 1-1-port2: hub_port_reset: no superspeed.
> > status:
> > 0. bail out
> > 11:43:56.752738: usb 1-1-port2: resume, status 0
> 
> And it's hard to tell exactly what that refers to.

https://elixir.bootlin.com/linux/v5.18-rc4/source/drivers/usb/core/hub.c#L3782

> 
> > 11:43:56.755442: usb 1-1-port2: port_event: call
> > hub_port_connect_change because connect_change is 1

this is 1 because change_bits has been read as "1" and
USB_PORT_STAT_C_CONNECTION is set.

> > 11:43:56.756663: usb 1-1-port2: status 0101, change 0004, 12 Mb/s
> > 11:43:56.756942: usb 1-1.2: hub_port_connect_change: not
> > resuscitating.

and here the udev->state is 7 (configured), so it's not resuscitated.

> > 11:43:56.762495: usb 1-1-port2: hub_port_connect_change: could not
> > revalidate the connection. call hub_port_connect.
> > 11:43:56.762797: usb 1-1.2: USB disconnect, device number 6
> > 11:43:56.765481: usb 1-1.2: unregistering device
> 
> It looks like these things happened after the reset-resume failed. 
> But 
> the control flow isn't clear (more log messages might help).

I'll resend with a bit more messages later. any specific other file
where the present debug messages would make sense? power management of
the qmi_wwan and generic usb drivers all look good.

> 
> > I'm sending this before analyzing it further. I'll do so soon but
> > wanted to show you that already.
> 
> Okay.  But it seems that the modem refused to be reset properly. 
> When 
> that happens there's no way to avoid disconnection.  And in fact I
> would 
> expect that re-initialization and enumeration would then be
> impossible, 
> since the first step of initialization is to perform a reset.

That's what gives me hope. re-initialization after "unregistering"
always (ok, almost, but we can assume always) works.


> 
> Alan Stern

again, I'm grateful that you talk that through with me. thanks a alot.

 martin

Re: USB device disconnects on resume

[Alan Stern]

On Fri, Apr 29, 2022 at 12:15:09PM +0200, Martin Kepplinger wrote:
> Am Donnerstag, dem 28.04.2022 um 15:13 -0400 schrieb Alan Stern:
> > On Thu, Apr 28, 2022 at 09:01:50AM +0200, Martin Kepplinger wrote:

I'll discuss what's going on, in greater detail...

> > > 11:43:50.800648: hub 1-1:1.0: hub_suspend
> > > 11:43:50.820074: usb 1-1: usb auto-suspend, wakeup 1
> > > 11:43:50.880637: usb 1-1: usb wakeup-resume
> > > 11:43:50.908646: usb 1-1: Waited 0ms for CONNECT
> > > 11:43:50.910445: usb 1-1: finish resume
> > > 11:43:50.911865: hub 1-1:1.0: hub_resume
> > > 11:43:50.913842: usb 1-1-port1: status 0507 change 0000
> > > 11:43:50.914026: usb 1-1-port2: status 0101 change 0005

That line is printed by hub_activate().  The 0001 bit in the "change" 
field is USB_PORT_STAT_C_CONNECTION.  hub_activate() clears it in line 
1178.

> > > 11:43:51.020887: usb usb1-port1: resume, status 0
> > > 11:43:51.021205: hub 1-1:1.0: state 7 ports 3 chg 0004 evt 0000

This line is printed at the start of hub_event().  It calls port_event() 
which calls hub_handle_remote_wakeup(), which calls usb_remote_wakeup(), 
which prints the next line:

> > > 11:43:51.048658: usb 1-1.2: usb wakeup-resume

Then usb_autoresume_device() ends up calling usb_port_resume()

> > > 11:43:51.076670: usb 1-1.2: Waited 0ms for CONNECT

That was from wait_for_connected().

> > > 11:43:51.078573: usb 1-1.2: finish reset-resume

Now we're in finish_port_resume() (including your 5-second delay), which 
calls usb_reset_and_verify_device(), which calls hub_port_init() in a 
loop. That routine starts by calling hub_port_reset().

> > > 11:43:56.305074: usb 1-1-port2: hub_port_reset: starting try 0 of 5

It issues a port reset and calls hub_port_wait_reset() to wait for the 
reset to complete.

> > > 11:43:56.328683: hub 1-1:1.0: port_wait_reset: err = -11
> > 
> > -EAGAIN means that the modem disconnected around the time of the
> > reset, 
> > so the reset failed.
> > 
> 
> ok, but we try up to 5 times and the second time below runs further,
> until the !hub_is_superspeed()
> 
> > > 11:43:56.333794: usb 1-1-port2: not enabled, trying reset again...
> > > 0 of
> > > 5. status=-11
> > > 11:43:56.334074: usb 1-1-port2: hub_port_reset: starting try 1 of 5

Okay, we try another reset.  But this time we don't see the return value 
from hub_port_wait_reset(), which means the value was 0, -ENOTCONN, or 
-ENODEV.  It would be nice to know what it really was.

> > > 11:43:56.536645: usb 1-1-port2: hub_port_reset: no superspeed.
> > > status:
> > > 0. bail out
> > 
> > Not sure what that means.
> 
> https://elixir.bootlin.com/linux/v5.18-rc4/source/drivers/usb/core/hub.c#L2995

That's not really bailing out.  Taking that goto means we are done 
trying to reset the device.  But what is the value of status?  I guess 
it must be 0, because if it weren't, hub_port_init() would follow its 
failure pathway.  Instead, it reached this line:

> > > 11:43:56.628824: usb 1-1.2: reset high-speed USB device number 6
> > > using
> > > xhci-hcd

and so the reset must have succeeded.  Now hub_port_init() issues a 
second reset as part of the normal device initialization procedure:

> > > 11:43:56.640305: usb 1-1-port2: hub_port_reset: starting try 0 of 5
> > > 11:43:56.656735: usb 1-1-port2: hub_port_reset: no superspeed.
> > > status:
> > > 0. bail out
> > > 11:43:56.752738: usb 1-1-port2: resume, status 0
> > 
> > And it's hard to tell exactly what that refers to.
> 
> https://elixir.bootlin.com/linux/v5.18-rc4/source/drivers/usb/core/hub.c#L3782

Which is back in hub_handle_remote_wakeup(), so evidently the entire 
reset succeeded and hub_port_init() should return 0.  It would be nice 
to verify this.

Anyway, it looks like the whole remote wakeup thing worked.

> > > 11:43:56.755442: usb 1-1-port2: port_event: call
> > > hub_port_connect_change because connect_change is 1
> 
> this is 1 because change_bits has been read as "1" and
> USB_PORT_STAT_C_CONNECTION is set.

Well, hub->change_bits certainly did cause connect_change to be 1, 
because hub_activate() set that bit in line 1241.  However the only 
reason for USB_PORT_STAT_C_CONNECTION to have been set when port_init() 
began would be if the modem disconnected itself again before it was 
reset.

Actually, that wouldn't be too surprising considering that the modem did 
disconnect itself during the first reset attempt.

> > > 11:43:56.756663: usb 1-1-port2: status 0101, change 0004, 12 Mb/s

This is printed at the start of hub_port_connect_change().  It indicates 
that the modem has once again disconnected itself, which must have 
happened at some point after the reset succeeded (which was only 4 ms 
earlier).  This is where the kernel gives up; it treats these
spontaneous disconnections the same as a real unplug.

> > > 11:43:56.756942: usb 1-1.2: hub_port_connect_change: not
> > > resuscitating.
> 
> and here the udev->state is 7 (configured), so it's not resuscitated.

Right.  The modem was resumed and reset, so at this point the port 
should have been enabled.  But it wasn't.  As far as the kernel is 
concerned, the modem is gone beyond hope of saving.

> > > 11:43:56.762495: usb 1-1-port2: hub_port_connect_change: could not
> > > revalidate the connection. call hub_port_connect.
> > > 11:43:56.762797: usb 1-1.2: USB disconnect, device number 6
> > > 11:43:56.765481: usb 1-1.2: unregistering device
> > 
> > It looks like these things happened after the reset-resume failed. 
> > But 
> > the control flow isn't clear (more log messages might help).

Going through it in more detail has shown that the reset did succeed but 
then the modem disconnected again afterward.  There isn't much we can do 
if the modem refuses to remain connected.

> I'll resend with a bit more messages later. any specific other file
> where the present debug messages would make sense? power management of
> the qmi_wwan and generic usb drivers all look good.

Not much else comes to mind.

> > > I'm sending this before analyzing it further. I'll do so soon but
> > > wanted to show you that already.
> > 
> > Okay.  But it seems that the modem refused to be reset properly. 
> > When 
> > that happens there's no way to avoid disconnection.  And in fact I
> > would 
> > expect that re-initialization and enumeration would then be
> > impossible, 
> > since the first step of initialization is to perform a reset.
> 
> That's what gives me hope. re-initialization after "unregistering"
> always (ok, almost, but we can assume always) works.

I don't see why re-initialization works any better.  It's not likely to 
be a question of waiting long enough, since you already waited for 5 
seconds.  There must be something different between the reset-resume and 
the re-initialization, but I can't tell what.

Maybe a usbmon trace showing the entire thing, both the reset-resume and 
the following re-initialization, would help.

Alan Stern

Re: USB device disconnects on resume

[Alan Stern]

On Mon, May 02, 2022 at 03:54:34PM +0200, Martin Kepplinger wrote:
> Am Freitag, dem 29.04.2022 um 16:21 -0400 schrieb Alan Stern:
> > I don't see why re-initialization works any better.  It's not likely
> > to 
> > be a question of waiting long enough, since you already waited for 5 
> > seconds.  There must be something different between the reset-resume
> > and 
> > the re-initialization, but I can't tell what.
> 
> Thanks for this great analysis and clarifications! It really looks like
> that difference is what I want to find.
> 
> > 
> > Maybe a usbmon trace showing the entire thing, both the reset-resume
> > and 
> > the following re-initialization, would help.
> > 
> 
> I append that here. A recording of the whole syslog until the modem is
> re-enumerated and working again. And the usbmon recording. I added a
> few usbmon timestampts to the kernel log to be able to correlate the 2
> a bit easier.

The usbmon trace shows that quite a lot happens during re-enumeration 
that doesn't happen during the reset-resume.  No doubt the reason for 
this is that the cdc-wdm driver doesn't have a real reset-resume 
handler; the operations it carries out for a reset-resume are the same 
as for a normal resume, and that clearly is not appropriate here.

For example, the usbmon trace shows that the kernel sends a 
Set-Interface request to the modem during re-enumeration and then does a 
whole lot of probing that I don't understand.  None of this stuff 
happens during the reset-resume.  Probably the modem decides that 
without any of this extra configuration, it doesn't need to do 
anything -- and that's why it disconnects itself.

So the person you need to talk to is the maintainer of the USB CDC 
drivers, Oliver Neukum (CC'ed).

Alan Stern

Re: USB device disconnects on resume

[Oliver Neukum]

On 02.05.22 21:32, Alan Stern wrote:

Hi,

I am happy to help, if I can.
> The usbmon trace shows that quite a lot happens during re-enumeration 
> that doesn't happen during the reset-resume.  No doubt the reason for 
> this is that the cdc-wdm driver doesn't have a real reset-resume 
> handler; the operations it carries out for a reset-resume are the same 
> as for a normal resume, and that clearly is not appropriate here.
Doing reset_resume() for WDM is problematic. The whole point
of WDM as a protocol is to put the configuration of a device
into user space. What is a kernel driver to do in that case.?
> For example, the usbmon trace shows that the kernel sends a 
> Set-Interface request to the modem during re-enumeration and then does a 
> whole lot of probing that I don't understand.  None of this stuff 
> happens during the reset-resume.  Probably the modem decides that 
> without any of this extra configuration, it doesn't need to do 
> anything -- and that's why it disconnects itself.
>

Are you sure that stuff comes from CDC-WDM in the case of reenumeration?
WDM does not do set_interface() in any case.

    Regards
        Oliver

Re: USB device disconnects on resume

[Alan Stern]

On Tue, May 03, 2022 at 09:36:16AM +0200, Oliver Neukum wrote:
> 
> 
> On 02.05.22 21:32, Alan Stern wrote:
> 
> Hi,
> 
> I am happy to help, if I can.
> > The usbmon trace shows that quite a lot happens during re-enumeration 
> > that doesn't happen during the reset-resume.  No doubt the reason for 
> > this is that the cdc-wdm driver doesn't have a real reset-resume 
> > handler; the operations it carries out for a reset-resume are the same 
> > as for a normal resume, and that clearly is not appropriate here.
> Doing reset_resume() for WDM is problematic. The whole point
> of WDM as a protocol is to put the configuration of a device
> into user space. What is a kernel driver to do in that case.?
> > For example, the usbmon trace shows that the kernel sends a 
> > Set-Interface request to the modem during re-enumeration and then does a 
> > whole lot of probing that I don't understand.  None of this stuff 
> > happens during the reset-resume.  Probably the modem decides that 
> > without any of this extra configuration, it doesn't need to do 
> > anything -- and that's why it disconnects itself.
> >
> 
> Are you sure that stuff comes from CDC-WDM in the case of reenumeration?
> WDM does not do set_interface() in any case.

No, I'm not at all sure where it comes from.  The kernel log mentions 
option and qmi_wwan, which may be relevant.

The email message containing the detailed usbmon trace and kernel log 
seems not to have gotten into the mailing list archives.  I'll put a 
copy of the log below for your reference.  (I can send the usbmon trace 
too, if you want to see it.)

Alan Stern


Apr 23 08:40:12.653806 pureos kernel: usb 1-1.2: usb auto-suspend, wakeup 1 - usbmon timestamp: 2311281195
Apr 23 08:40:12.677790 pureos kernel: hub 1-1:1.0: hub_suspend - usbmon timestamp: 2311304057
Apr 23 08:40:12.701770 pureos kernel: usb 1-1: usb auto-suspend, wakeup 1 - usbmon timestamp: 2311328158
Apr 23 08:40:12.729785 pureos kernel: hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002
Apr 23 08:40:12.754308 pureos kernel: usb 1-1: usb wakeup-resume - usbmon timestamp: 2311380045
Apr 23 08:40:12.774292 pureos kernel: usb 1-1: Waited 0ms for CONNECT
Apr 23 08:40:12.775803 pureos kernel: usb 1-1: finish resume
Apr 23 08:40:12.776877 pureos kernel: hub 1-1:1.0: hub_resume - usbmon timestamp: 2311400717
Apr 23 08:40:12.777982 pureos kernel: usb 1-1-port1: status 0507 change 0000
Apr 23 08:40:12.778118 pureos kernel: usb 1-1-port2: status 0101 change 0005
Apr 23 08:40:12.882293 pureos kernel: usb usb1-port1: resume, status 0
Apr 23 08:40:12.882720 pureos kernel: hub 1-1:1.0: state 7 ports 3 chg 0004 evt 0000
Apr 23 08:40:12.901864 pureos kernel: usb 1-1.2: usb wakeup-resume - usbmon timestamp: 2311528048
Apr 23 08:40:12.925809 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
Apr 23 08:40:12.927336 pureos kernel: usb 1-1.2: finish reset-resume
Apr 23 08:40:13.033801 pureos kernel: usb 1-1.2: reset high-speed USB device number 8 using xhci-hcd
Apr 23 08:40:13.162832 pureos kernel: usb 1-1-port2: resume, status 0
Apr 23 08:40:13.163251 pureos kernel: usb 1-1-port2: status 0101, change 0004, 12 Mb/s
Apr 23 08:40:13.163448 pureos kernel: usb 1-1.2: USB disconnect, device number 8
Apr 23 08:40:13.164732 pureos kernel: usb 1-1.2: unregistering device
Apr 23 08:40:13.165999 pureos kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Apr 23 08:40:13.166329 pureos kernel: option 1-1.2:1.0: device disconnected
Apr 23 08:40:13.170341 pureos kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Apr 23 08:40:13.170874 pureos kernel: option 1-1.2:1.1: device disconnected
Apr 23 08:40:13.171193 pureos kernel: option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Apr 23 08:40:13.171405 pureos kernel: option 1-1.2:1.2: device disconnected
Apr 23 08:40:13.171625 pureos kernel: option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
Apr 23 08:40:13.171822 pureos kernel: option 1-1.2:1.3: device disconnected
Apr 23 08:40:13.178717 pureos kernel: qmi_wwan 1-1.2:1.4 wwx0254efef4d47: unregister 'qmi_wwan' usb-xhci-hcd.4.auto-1.2, WWAN/QMI device
Apr 23 08:40:13.173382 pureos systemd-networkd[386]: wwx0254efef4d47: Link DOWN
Apr 23 08:40:13.173668 pureos ModemManager[573]: Cannot read from istream: connection broken
Apr 23 08:40:13.173423 pureos systemd-networkd[386]: wwx0254efef4d47: Lost carrier
Apr 23 08:40:13.173790 pureos ModemManager[573]: [/dev/cdc-wdm0] QMI endpoint hangup: removed
Apr 23 08:40:13.178093 pureos systemd-timesyncd[460]: No network connectivity, watching for changes.
Apr 23 08:40:13.173850 pureos ModemManager[573]: <info>  [modem6] connection to qmi-proxy for /dev/cdc-wdm0 lost, reprobing
Apr 23 08:40:13.183805 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_modem_unavailable() Disabling Bearer Handler
Apr 23 08:40:13.174943 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
Apr 23 08:40:13.183841 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler (nil)
Apr 23 08:40:13.174993 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '3'
Apr 23 08:40:13.183865 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_disconnect_from_sms_wap() Stopping watching SMS WAPs
Apr 23 08:40:13.175165 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
Apr 23 08:40:13.184369 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Modem vanished, Disabling plugin
Apr 23 08:40:13.175206 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '2'
Apr 23 08:40:13.184395 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_NO_MODEM
Apr 23 08:40:13.175307 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'voice' client with flags 'release-cid'...
Apr 23 08:40:13.184423 pureos mmsdtng[748]: ../plugins/modemmanager.c:cb_object_removed() Modem removed: /org/freedesktop/ModemManager1/Modem/6
Apr 23 08:40:13.180791 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'voice' client with ID '2'
Apr 23 08:40:13.195056 pureos NetworkManager[497]: <info>  [1650696013.1949] device (cdc-wdm0): state change: activated -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Apr 23 08:40:13.190435 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'pdc' client with flags 'release-cid'...
Apr 23 08:40:13.190496 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'pdc' client with ID '1'
Apr 23 08:40:13.190665 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'loc' client with flags 'release-cid'...
Apr 23 08:40:13.190706 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'loc' client with ID '1'
Apr 23 08:40:13.190811 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'uim' client with flags 'release-cid'...
Apr 23 08:40:13.190856 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'uim' client with ID '1'
Apr 23 08:40:13.190958 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'wms' client with flags 'release-cid'...
Apr 23 08:40:13.190997 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'wms' client with ID '1'
Apr 23 08:40:13.191100 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
Apr 23 08:40:13.191145 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '1'
Apr 23 08:40:13.191257 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'nas' client with flags 'release-cid'...
Apr 23 08:40:13.191297 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'nas' client with ID '1'
Apr 23 08:40:13.191407 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'dms' client with flags 'release-cid'...
Apr 23 08:40:13.191447 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'dms' client with ID '1'
Apr 23 08:40:13.230747 pureos NetworkManager[497]: <info>  [1650696013.2306] manager: NetworkManager state is now DISCONNECTED
Apr 23 08:40:13.237015 pureos upowerd[845]: treating change event as add on /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2
Apr 23 08:40:13.277335 pureos ModemManager[573]: <info>  [base-manager] port ttyUSB1 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2'
Apr 23 08:40:13.286260 pureos ModemManager[573]: <info>  [base-manager] port ttyUSB2 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2'
Apr 23 08:40:13.291472 pureos ModemManager[573]: <info>  [base-manager] port ttyUSB0 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2'
Apr 23 08:40:13.295778 pureos ModemManager[573]: <info>  [base-manager] port ttyUSB3 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2'
Apr 23 08:40:13.306334 pureos kernel: usb 1-1.2: new high-speed USB device number 9 using xhci-hcd
Apr 23 08:40:13.329268 pureos ModemManager[573]: <info>  [base-manager] port cdc-wdm0 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2'
Apr 23 08:40:13.331681 pureos NetworkManager[497]: <warn>  [1650696013.3315] dns-sd-resolved[85a0ffe846d22b1a]: send-updates SetLinkDomains@7 failed: GDBus.Error:org.freedesktop.resolve1.NoSuchLink: Link 7 not known
Apr 23 08:40:13.388236 pureos dbus-daemon[486]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.9' (uid=0 pid=497 comm="/usr/sbin/NetworkManager --no-daemon ")
Apr 23 08:40:13.398537 pureos systemd[1]: Starting Network Manager Script Dispatcher Service...
Apr 23 08:40:13.406276 pureos kernel: usb 1-1.2: udev 9, busnum 1, minor = 8
Apr 23 08:40:13.407671 pureos kernel: usb 1-1.2: New USB device found, idVendor=2020, idProduct=2060, bcdDevice= 0.00
Apr 23 08:40:13.408775 pureos kernel: usb 1-1.2: New USB device strings: Mfr=3, Product=2, SerialNumber=4
Apr 23 08:40:13.409778 pureos kernel: usb 1-1.2: Product: Qualcomm CDMA Technologies MSM
Apr 23 08:40:13.410753 pureos kernel: usb 1-1.2: Manufacturer: Qualcomm, Incorporated
Apr 23 08:40:13.427146 pureos NetworkManager[497]: <warn>  [1650696013.4270] modem-broadband[cdc-wdm0]: failed to disconnect modem: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.ModemManager1.Modem.Simple” on object at path /org/freedesktop/ModemManager1/Modem/6
Apr 23 08:40:13.428954 pureos ModemManager[573]: <info>  [base-manager] port wwx0254efef4d47 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2'
Apr 23 08:40:13.514548 pureos kernel: option 1-1.2:1.0: GSM modem (1-port) converter detected
Apr 23 08:40:13.519078 pureos kernel: usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB0
Apr 23 08:40:13.520372 pureos kernel: option 1-1.2:1.1: GSM modem (1-port) converter detected
Apr 23 08:40:13.524791 pureos kernel: usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB1
Apr 23 08:40:13.531525 pureos kernel: option 1-1.2:1.2: GSM modem (1-port) converter detected
Apr 23 08:40:13.533448 pureos kernel: usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB2
Apr 23 08:40:13.536436 pureos kernel: option 1-1.2:1.3: GSM modem (1-port) converter detected
Apr 23 08:40:13.538577 pureos kernel: usb 1-1.2: GSM modem (1-port) converter now attached to ttyUSB3
Apr 23 08:40:13.528423 pureos systemd[1]: Started Network Manager Script Dispatcher Service.
Apr 23 08:40:13.526818 pureos dbus-daemon[486]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Apr 23 08:40:13.547926 pureos kernel: qmi_wwan 1-1.2:1.4: cdc-wdm0: USB WDM device
Apr 23 08:40:13.550669 pureos kernel: qmi_wwan 1-1.2:1.4 wwan0: register 'qmi_wwan' at usb-xhci-hcd.4.auto-1.2, WWAN/QMI device, 02:54:ef:ef:4d:47
Apr 23 08:40:13.562725 pureos upowerd[845]: treating change event as add on /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2
Apr 23 08:40:13.631393 pureos mtp-probe[4156]: checking bus 1, device 9: "/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2"
Apr 23 08:40:13.660094 pureos mtp-probe[4156]: bus: 1, device: 9 was not an MTP device
Apr 23 08:40:13.718475 pureos upowerd[845]: treating change event as add on /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2
Apr 23 08:40:13.792506 pureos systemd-udevd[4135]: Using default interface naming scheme 'v247'.
Apr 23 08:40:13.808553 pureos systemd-udevd[4135]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Apr 23 08:40:13.813814 pureos kernel: qmi_wwan 1-1.2:1.4 wwx0254efef4d47: renamed from wwan0
Apr 23 08:40:13.844331 pureos systemd-networkd[386]: wwan0: Interface name change detected, wwan0 has been renamed to wwx0254efef4d47.
Apr 23 08:40:13.940121 pureos dbus-daemon[756]: [session uid=1000 pid=756] Activating via systemd: service name='org.freedesktop.Tracker1.Miner.Extract' unit='tracker-extract.service' requested by ':1.3' (uid=1000 pid=754 comm="/usr/libexec/tracker-miner-fs ")
Apr 23 08:40:14.014749 pureos systemd[730]: Starting Tracker metadata extractor...
Apr 23 08:40:14.087366 pureos tracker-extract[4193]: Set scheduler policy to SCHED_IDLE
Apr 23 08:40:14.092298 pureos tracker-extract[4193]: Setting priority nice level to 19
Apr 23 08:40:14.128385 pureos mtp-probe[4196]: checking bus 1, device 9: "/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2"
Apr 23 08:40:14.166884 pureos mtp-probe[4196]: bus: 1, device: 9 was not an MTP device
Apr 23 08:40:14.180618 pureos systemd-udevd[4137]: Using default interface naming scheme 'v247'.
Apr 23 08:40:14.186303 pureos systemd-udevd[4137]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Apr 23 08:40:14.214499 pureos goa-daemon[816]: goa_http_client_check() failed: 2 — Fehler beim Auflösen von »cloud.puri.sm«: Der Name oder der Dienst ist nicht bekannt
Apr 23 08:40:14.215420 pureos goa-daemon[816]: /org/gnome/OnlineAccounts/Accounts/account_1638277513_0: Setting AttentionNeeded to TRUE because EnsureCredentials() failed with: Ungültiges Passwort für Benutzer »martin.kepplinger@puri.sm« (goa-error-quark, 0): Rechnername konnte nicht aufgelöst werden (goa-error-quark, 4)
Apr 23 08:40:15.011361 pureos dbus-daemon[756]: [session uid=1000 pid=756] Successfully activated service 'org.freedesktop.Tracker1.Miner.Extract'
Apr 23 08:40:15.014491 pureos systemd[730]: Started Tracker metadata extractor.
Apr 23 08:40:15.218774 pureos goa-daemon[816]: goa_http_client_check() failed: 2 — Fehler beim Auflösen von »cloud.puri.sm«: Der Name oder der Dienst ist nicht bekannt
Apr 23 08:40:15.337345 pureos ModemManager[573]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
Apr 23 08:40:15.337935 pureos ModemManager[573]: [/dev/cdc-wdm0] created endpoint
Apr 23 08:40:15.342367 pureos ModemManager[573]: [/dev/cdc-wdm0] Checking version info (45 retries)...
Apr 23 08:40:15.349704 pureos ModemManager[573]: [/dev/cdc-wdm0] QMI Device supports 30 services:
Apr 23 08:40:15.349807 pureos ModemManager[573]: [/dev/cdc-wdm0]    ctl (1.5)
Apr 23 08:40:15.349838 pureos ModemManager[573]: [/dev/cdc-wdm0]    wds (1.67)
Apr 23 08:40:15.349868 pureos ModemManager[573]: [/dev/cdc-wdm0]    dms (1.0)
Apr 23 08:40:15.349896 pureos ModemManager[573]: [/dev/cdc-wdm0]    nas (1.25)
Apr 23 08:40:15.349925 pureos ModemManager[573]: [/dev/cdc-wdm0]    qos (1.12)
Apr 23 08:40:15.349954 pureos ModemManager[573]: [/dev/cdc-wdm0]    wms (1.10)
Apr 23 08:40:15.349983 pureos ModemManager[573]: [/dev/cdc-wdm0]    auth (1.3)
Apr 23 08:40:15.350011 pureos ModemManager[573]: [/dev/cdc-wdm0]    at (1.4)
Apr 23 08:40:15.350039 pureos ModemManager[573]: [/dev/cdc-wdm0]    voice (2.1)
Apr 23 08:40:15.350067 pureos ModemManager[573]: [/dev/cdc-wdm0]    cat2 (2.24)
Apr 23 08:40:15.350095 pureos ModemManager[573]: [/dev/cdc-wdm0]    uim (1.46)
Apr 23 08:40:15.350123 pureos ModemManager[573]: [/dev/cdc-wdm0]    pbm (1.4)
Apr 23 08:40:15.350151 pureos ModemManager[573]: [/dev/cdc-wdm0]    test (1.0)
Apr 23 08:40:15.350179 pureos ModemManager[573]: [/dev/cdc-wdm0]    loc (2.0)
Apr 23 08:40:15.350206 pureos ModemManager[573]: [/dev/cdc-wdm0]    sar (1.0)
Apr 23 08:40:15.350234 pureos ModemManager[573]: [/dev/cdc-wdm0]    ims (1.0)
Apr 23 08:40:15.350266 pureos ModemManager[573]: [/dev/cdc-wdm0]    csd (1.0)
Apr 23 08:40:15.350294 pureos ModemManager[573]: [/dev/cdc-wdm0]    ts (1.0)
Apr 23 08:40:15.350322 pureos ModemManager[573]: [/dev/cdc-wdm0]    tmd (1.0)
Apr 23 08:40:15.350350 pureos ModemManager[573]: [/dev/cdc-wdm0]    wda (1.16)
Apr 23 08:40:15.350379 pureos ModemManager[573]: [/dev/cdc-wdm0]    csvt (1.1)
Apr 23 08:40:15.350408 pureos ModemManager[573]: [/dev/cdc-wdm0]    imsp (1.0)
Apr 23 08:40:15.350730 pureos ModemManager[573]: [/dev/cdc-wdm0]    imsa (1.0)
Apr 23 08:40:15.350767 pureos ModemManager[573]: [/dev/cdc-wdm0]    coex (1.0)
Apr 23 08:40:15.350798 pureos ModemManager[573]: [/dev/cdc-wdm0]    pdc (1.0)
Apr 23 08:40:15.350827 pureos ModemManager[573]: [/dev/cdc-wdm0]    rfrpe (1.0)
Apr 23 08:40:15.350856 pureos ModemManager[573]: [/dev/cdc-wdm0]    dsd (1.0)
Apr 23 08:40:15.350887 pureos ModemManager[573]: [/dev/cdc-wdm0]    unknown [0x2d] (1.0)
Apr 23 08:40:15.350916 pureos ModemManager[573]: [/dev/cdc-wdm0]    unknown [0x30] (1.0)
Apr 23 08:40:15.350943 pureos ModemManager[573]: [/dev/cdc-wdm0]    unknown [0x36] (1.0)
Apr 23 08:40:16.331469 pureos ModemManager[573]: <info>  [device /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2] creating modem with plugin 'broadmobi' and '6' ports
Apr 23 08:40:16.334533 pureos ModemManager[573]: <info>  [base-manager] modem for device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2' successfully created
Apr 23 08:40:16.334739 pureos ModemManager[573]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
Apr 23 08:40:16.335175 pureos ModemManager[573]: [/dev/cdc-wdm0] created endpoint
Apr 23 08:40:16.337322 pureos ModemManager[573]: [/dev/cdc-wdm0] Checking version info (45 retries)...
Apr 23 08:40:16.341555 pureos ModemManager[573]: [/dev/cdc-wdm0] QMI Device supports 30 services:
Apr 23 08:40:16.341602 pureos ModemManager[573]: [/dev/cdc-wdm0]    ctl (1.5)
Apr 23 08:40:16.341632 pureos ModemManager[573]: [/dev/cdc-wdm0]    wds (1.67)
Apr 23 08:40:16.341660 pureos ModemManager[573]: [/dev/cdc-wdm0]    dms (1.0)
Apr 23 08:40:16.341690 pureos ModemManager[573]: [/dev/cdc-wdm0]    nas (1.25)
Apr 23 08:40:16.341738 pureos ModemManager[573]: [/dev/cdc-wdm0]    qos (1.12)
Apr 23 08:40:16.341771 pureos ModemManager[573]: [/dev/cdc-wdm0]    wms (1.10)
Apr 23 08:40:16.341800 pureos ModemManager[573]: [/dev/cdc-wdm0]    auth (1.3)
Apr 23 08:40:16.341829 pureos ModemManager[573]: [/dev/cdc-wdm0]    at (1.4)
Apr 23 08:40:16.341857 pureos ModemManager[573]: [/dev/cdc-wdm0]    voice (2.1)
Apr 23 08:40:16.341884 pureos ModemManager[573]: [/dev/cdc-wdm0]    cat2 (2.24)
Apr 23 08:40:16.341914 pureos ModemManager[573]: [/dev/cdc-wdm0]    uim (1.46)
Apr 23 08:40:16.341942 pureos ModemManager[573]: [/dev/cdc-wdm0]    pbm (1.4)
Apr 23 08:40:16.341970 pureos ModemManager[573]: [/dev/cdc-wdm0]    test (1.0)
Apr 23 08:40:16.341999 pureos ModemManager[573]: [/dev/cdc-wdm0]    loc (2.0)
Apr 23 08:40:16.342027 pureos ModemManager[573]: [/dev/cdc-wdm0]    sar (1.0)
Apr 23 08:40:16.342056 pureos ModemManager[573]: [/dev/cdc-wdm0]    ims (1.0)
Apr 23 08:40:16.342085 pureos ModemManager[573]: [/dev/cdc-wdm0]    csd (1.0)
Apr 23 08:40:16.342114 pureos ModemManager[573]: [/dev/cdc-wdm0]    ts (1.0)
Apr 23 08:40:16.342142 pureos ModemManager[573]: [/dev/cdc-wdm0]    tmd (1.0)
Apr 23 08:40:16.342170 pureos ModemManager[573]: [/dev/cdc-wdm0]    wda (1.16)
Apr 23 08:40:16.342198 pureos ModemManager[573]: [/dev/cdc-wdm0]    csvt (1.1)
Apr 23 08:40:16.342227 pureos ModemManager[573]: [/dev/cdc-wdm0]    imsp (1.0)
Apr 23 08:40:16.342255 pureos ModemManager[573]: [/dev/cdc-wdm0]    imsa (1.0)
Apr 23 08:40:16.342282 pureos ModemManager[573]: [/dev/cdc-wdm0]    coex (1.0)
Apr 23 08:40:16.342310 pureos ModemManager[573]: [/dev/cdc-wdm0]    pdc (1.0)
Apr 23 08:40:16.342338 pureos ModemManager[573]: [/dev/cdc-wdm0]    rfrpe (1.0)
Apr 23 08:40:16.342367 pureos ModemManager[573]: [/dev/cdc-wdm0]    dsd (1.0)
Apr 23 08:40:16.342397 pureos ModemManager[573]: [/dev/cdc-wdm0]    unknown [0x2d] (1.0)
Apr 23 08:40:16.342425 pureos ModemManager[573]: [/dev/cdc-wdm0]    unknown [0x30] (1.0)
Apr 23 08:40:16.342454 pureos ModemManager[573]: [/dev/cdc-wdm0]    unknown [0x36] (1.0)
Apr 23 08:40:16.342590 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.345805 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'wda' (version 1.16) client with ID '1'
Apr 23 08:40:16.351668 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.351832 pureos ModemManager[573]: [/dev/cdc-wdm0] Releasing 'wda' client with flags 'release-cid'...
Apr 23 08:40:16.351874 pureos ModemManager[573]: [/dev/cdc-wdm0] Unregistered 'wda' client with ID '1'
Apr 23 08:40:16.356077 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'dms' (version 1.0) client with ID '1'
Apr 23 08:40:16.356153 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.360039 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'nas' (version 1.25) client with ID '1'
Apr 23 08:40:16.360114 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.366150 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'wds' (version 1.67) client with ID '1'
Apr 23 08:40:16.366228 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.369578 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'wms' (version 1.10) client with ID '1'
Apr 23 08:40:16.369858 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.373631 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'uim' (version 1.46) client with ID '1'
Apr 23 08:40:16.373706 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.377591 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'loc' (version 2.0) client with ID '1'
Apr 23 08:40:16.377662 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.381060 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'pdc' (version 1.0) client with ID '1'
Apr 23 08:40:16.381137 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.385090 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'voice' (version 2.1) client with ID '2'
Apr 23 08:40:16.452902 pureos ModemManager[573]: <warn>  [modem7] couldn't query SIM slots: QMI protocol error (94): 'NotSupported'
Apr 23 08:40:16.525289 pureos ModemManager[573]: <warn>  [modem7/sim6] couldn't load list of emergency numbers: uninitialized emergency numbers list
Apr 23 08:40:16.650604 pureos ModemManager[573]: <info>  [modem7] state changed (unknown -> disabled)
Apr 23 08:40:16.677306 pureos mmsdtng[748]: ../plugins/modemmanager.c:cb_object_added() cb_object_added
Apr 23 08:40:16.679627 pureos mmsdtng[748]: New Object with Messaging feature found, Adding...
Apr 23 08:40:16.680648 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_add_object() Not checking for a default Modem
Apr 23 08:40:16.681611 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_add_object() Added device at: /org/freedesktop/ModemManager1/Modem/7
Apr 23 08:40:16.682685 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_init_modem() mmsd_mm_init_modem
Apr 23 08:40:16.685897 pureos NetworkManager[497]: <info>  [1650696016.6857] modem["cdc-wdm0"]: modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Apr 23 08:40:16.689921 pureos NetworkManager[497]: <info>  [1650696016.6898] manager: (cdc-wdm0): new Broadband device (/org/freedesktop/NetworkManager/Devices/8)
Apr 23 08:40:16.693981 pureos NetworkManager[497]: <info>  [1650696016.6938] device (cdc-wdm0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Apr 23 08:40:16.697684 pureos NetworkManager[497]: <info>  [1650696016.6975] device (cdc-wdm0): modem state 'enabling'
Apr 23 08:40:16.702416 pureos NetworkManager[497]: <info>  [1650696016.7022] device (cdc-wdm0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:16.704895 pureos NetworkManager[497]: <info>  [1650696016.7047] policy: auto-activating connection 'HoT' (c9aa442f-4ae3-4752-974d-6208792de208)
Apr 23 08:40:16.707675 pureos NetworkManager[497]: <info>  [1650696016.7075] device (cdc-wdm0): Activation: starting connection 'HoT' (c9aa442f-4ae3-4752-974d-6208792de208)
Apr 23 08:40:16.708267 pureos NetworkManager[497]: <info>  [1650696016.7082] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:16.714585 pureos NetworkManager[497]: <info>  [1650696016.7144] manager: NetworkManager state is now CONNECTING
Apr 23 08:40:16.751327 pureos mmsdtng[748]: ../src/service.c:mms_service_set_country_code() Service Country Code set to AT
Apr 23 08:40:16.752138 pureos mmsdtng[748]: ../src/service.c:mms_service_set_own_number() Service own number set
Apr 23 08:40:16.752201 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_connect_to_sms_wap() Watching for new SMS WAPs
Apr 23 08:40:16.752266 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() Something May be wrong with the modem, checking....
Apr 23 08:40:16.752292 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() MM_MODEM_STATE_DISABLED
Apr 23 08:40:16.752318 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Modem disabled
Apr 23 08:40:16.752341 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_MODEM_DISABLED
Apr 23 08:40:16.752364 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Disabling Bearer Handler
Apr 23 08:40:16.752389 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler (nil)
Apr 23 08:40:16.768383 pureos mmsdtng[748]: ../src/service.c:handle_method_call_manager() At Get Services Method Call
Apr 23 08:40:16.789417 pureos mmsdtng[748]: ../src/service.c:handle_method_call_service() Retrieving all Messages...
Apr 23 08:40:16.789493 pureos mmsdtng[748]: ../src/service.c:handle_method_call_service() No Messages!
Apr 23 08:40:16.822795 pureos ModemManager[573]: <info>  [modem7] state changed (disabled -> enabling)
Apr 23 08:40:16.831513 pureos mmsdtng[748]: ../plugins/modemmanager.c:modem_state_changed_cb() State Change: Old State: 3 New State: 5, Reason: 1
Apr 23 08:40:16.831574 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() Something May be wrong with the modem, checking....
Apr 23 08:40:16.831599 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() MM_MODEM_STATE_ENABLING
Apr 23 08:40:16.831623 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Modem disabled
Apr 23 08:40:16.831644 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_MODEM_DISABLED
Apr 23 08:40:16.831669 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Disabling Bearer Handler
Apr 23 08:40:16.834962 pureos ModemManager[573]: <info>  [modem7] power state updated: on
Apr 23 08:40:16.831696 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler (nil)
Apr 23 08:40:16.839704 pureos ModemManager[573]: <info>  [modem7] simple connect started...
Apr 23 08:40:16.839805 pureos ModemManager[573]: <info>  [modem7] simple connect state (4/8): wait to get fully enabled
Apr 23 08:40:16.913042 pureos ModemManager[573]: <info>  [modem7] state changed (enabling -> enabled)
Apr 23 08:40:16.913244 pureos ModemManager[573]: <info>  [modem7] simple connect state (5/8): register
Apr 23 08:40:16.917943 pureos ModemManager[573]: <info>  [modem7] 3GPP registration state changed (unknown -> registering)
Apr 23 08:40:16.920700 pureos NetworkManager[497]: <info>  [1650696016.9205] modem["cdc-wdm0"]: modem state changed, 'enabling' --> 'enabled' (reason: user-requested)
Apr 23 08:40:16.921192 pureos mmsdtng[748]: ../plugins/modemmanager.c:modem_state_changed_cb() State Change: Old State: 5 New State: 6, Reason: 1
Apr 23 08:40:16.921221 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() MM_MODEM_GOOD_STATE: 6
Apr 23 08:40:16.921245 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_READY
Apr 23 08:40:16.921268 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Setting Bearer Handler
Apr 23 08:40:16.921293 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler 0xaaaae09a52f0
Apr 23 08:40:16.921318 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_get_all_sms() Queue Search for all SMS
Apr 23 08:40:16.924842 pureos ModemManager[573]: <info>  [modem7] 3GPP registration state changed (registering -> home)
Apr 23 08:40:16.925031 pureos ModemManager[573]: <info>  [modem7] state changed (enabled -> registered)
Apr 23 08:40:16.928260 pureos ModemManager[573]: <info>  [modem7] simple connect state (6/8): bearer
Apr 23 08:40:16.931994 pureos NetworkManager[497]: <info>  [1650696016.9318] modem["cdc-wdm0"]: modem state changed, 'enabled' --> 'registered' (reason: unknown)
Apr 23 08:40:16.935170 pureos ModemManager[573]: <info>  [modem7] simple connect state (7/8): connect
Apr 23 08:40:16.937529 pureos ModemManager[573]: <info>  [modem7] state changed (registered -> connecting)
Apr 23 08:40:16.939634 pureos mmsdtng[748]: ../plugins/modemmanager.c:modem_state_changed_cb() State Change: Old State: 6 New State: 8, Reason: 0
Apr 23 08:40:16.941081 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:16.939692 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() MM_MODEM_GOOD_STATE: 8
Apr 23 08:40:16.939717 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_READY
Apr 23 08:40:16.939740 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Setting Bearer Handler
Apr 23 08:40:16.939766 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler 0xaaaae09a52f0
Apr 23 08:40:16.948575 pureos mmsdtng[748]: ../plugins/modemmanager.c:modem_state_changed_cb() State Change: Old State: 8 New State: 10, Reason: 1
Apr 23 08:40:16.948607 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() MM_MODEM_GOOD_STATE: 10
Apr 23 08:40:16.948631 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_READY
Apr 23 08:40:16.948654 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Setting Bearer Handler
Apr 23 08:40:16.948680 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler 0xaaaae09a52f0
Apr 23 08:40:16.956714 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'wds' (version 1.67) client with ID '2'
Apr 23 08:40:16.952008 pureos NetworkManager[497]: <info>  [1650696016.9518] modem["cdc-wdm0"]: modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Apr 23 08:40:17.014186 pureos ModemManager[573]: <info>  [modem7/bearer9] QMI IPv4 Settings:
Apr 23 08:40:17.014262 pureos ModemManager[573]: <info>  [modem7/bearer9]     address: 10.151.253.61/30
Apr 23 08:40:17.014302 pureos ModemManager[573]: <info>  [modem7/bearer9]     gateway: 10.151.253.62
Apr 23 08:40:17.014337 pureos ModemManager[573]: <info>  [modem7/bearer9]     DNS #1: 213.162.70.9
Apr 23 08:40:17.014370 pureos ModemManager[573]: <info>  [modem7/bearer9]     DNS #2: 213.162.70.25
Apr 23 08:40:17.014404 pureos ModemManager[573]: <info>  [modem7/bearer9]        MTU: 1500
Apr 23 08:40:17.014478 pureos ModemManager[573]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 23 08:40:17.017977 pureos ModemManager[573]: [/dev/cdc-wdm0] Registered 'wds' (version 1.67) client with ID '3'
Apr 23 08:40:17.035198 pureos ModemManager[573]: <info>  [modem7/bearer9] couldn't start network: QMI protocol error (14): 'CallFailed'
Apr 23 08:40:17.035260 pureos ModemManager[573]: <info>  [modem7/bearer9] verbose call end reason (2,237): [internal] interface-in-use
Apr 23 08:40:17.036155 pureos ModemManager[573]: <info>  [modem7] state changed (connecting -> connected)
Apr 23 08:40:17.037027 pureos ModemManager[573]: <info>  [modem7] simple connect state (8/8): all done
Apr 23 08:40:17.042875 pureos mmsdtng[748]: ../plugins/modemmanager.c:modem_state_changed_cb() State Change: Old State: 10 New State: 11, Reason: 1
Apr 23 08:40:17.042909 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_modem_state() MM_MODEM_GOOD_STATE: 11
Apr 23 08:40:17.042933 pureos NetworkManager[497]: <info>  [1650696017.0428] modem["cdc-wdm0"]: modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Apr 23 08:40:17.042934 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() MMSD_MM_STATE_READY
Apr 23 08:40:17.042959 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_state() Setting Bearer Handler
Apr 23 08:40:17.042984 pureos mmsdtng[748]: ../src/service.c:mms_service_set_bearer_handler() service 0xaaaaea6c1cf0 handler 0xaaaae09a52f0
Apr 23 08:40:17.043011 pureos mmsdtng[748]: ../plugins/modemmanager.c:process_mms_process_message_queue() Processing any unsent/unreceived MMS messages.
Apr 23 08:40:17.066838 pureos systemd-networkd[386]: wwx0254efef4d47: Link UP
Apr 23 08:40:17.066881 pureos systemd-networkd[386]: wwx0254efef4d47: Gained carrier
Apr 23 08:40:17.069398 pureos NetworkManager[497]: <info>  [1650696017.0693] device (cdc-wdm0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:17.071330 pureos NetworkManager[497]: <info>  [1650696017.0712] device (cdc-wdm0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:17.072416 pureos NetworkManager[497]: <info>  [1650696017.0723] modem["cdc-wdm0"]: IPv6 configuration disabled
Apr 23 08:40:17.072538 pureos NetworkManager[497]: <info>  [1650696017.0724] modem-broadband[cdc-wdm0]: IPv4 static configuration:
Apr 23 08:40:17.072686 pureos NetworkManager[497]: <info>  [1650696017.0726] modem-broadband[cdc-wdm0]:   address 10.151.253.61/30
Apr 23 08:40:17.072755 pureos NetworkManager[497]: <info>  [1650696017.0727] modem-broadband[cdc-wdm0]:   gateway 10.151.253.62
Apr 23 08:40:17.072812 pureos NetworkManager[497]: <info>  [1650696017.0727] modem-broadband[cdc-wdm0]:   DNS 213.162.70.9
Apr 23 08:40:17.072863 pureos NetworkManager[497]: <info>  [1650696017.0728] modem-broadband[cdc-wdm0]:   DNS 213.162.70.25
Apr 23 08:40:17.072905 pureos NetworkManager[497]: <info>  [1650696017.0728] modem-broadband[cdc-wdm0]:   MTU 1500
Apr 23 08:40:17.081811 pureos systemd-timesyncd[460]: Network configuration changed, trying to establish connection.
Apr 23 08:40:17.100451 pureos NetworkManager[497]: <info>  [1650696017.1003] device (cdc-wdm0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:17.133996 pureos NetworkManager[497]: <info>  [1650696017.1338] device (cdc-wdm0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:17.135262 pureos NetworkManager[497]: <info>  [1650696017.1351] device (cdc-wdm0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Apr 23 08:40:17.137242 pureos NetworkManager[497]: <info>  [1650696017.1371] manager: NetworkManager state is now CONNECTED_LOCAL
Apr 23 08:40:17.147972 pureos NetworkManager[497]: <info>  [1650696017.1478] manager: NetworkManager state is now CONNECTED_SITE
Apr 23 08:40:17.158030 pureos NetworkManager[497]: <info>  [1650696017.1579] policy: set 'HoT' (wwx0254efef4d47) as default for IPv4 routing and DNS
Apr 23 08:40:17.162499 pureos NetworkManager[497]: <info>  [1650696017.1624] device (cdc-wdm0): Activation: successful, device activated.
Apr 23 08:40:17.647327 pureos NetworkManager[497]: <info>  [1650696017.6472] manager: NetworkManager state is now CONNECTED_GLOBAL
Apr 23 08:40:18.312412 pureos mmsdtng[748]: ../src/service.c:activate_bearer() service 0xaaaaea6c1cf0 setup 0 active 0
Apr 23 08:40:18.312462 pureos mmsdtng[748]: ../src/service.c:activate_bearer() service 0xaaaaea6c1cf0 waiting for 20 seconds
Apr 23 08:40:18.312501 pureos mmsdtng[748]: ../plugins/modemmanager.c:set_context() Setting Context...
Apr 23 08:40:18.312526 pureos mmsdtng[748]: ../src/service.c:mms_service_set_mmsc() service 0xaaaaea6c1cf0 mmsc http://mms.invalid
Apr 23 08:40:18.312581 pureos mmsdtng[748]: ../plugins/modemmanager.c:set_context() Max number of bearers: 1
Apr 23 08:40:18.322627 pureos mmsdtng[748]: ../plugins/modemmanager.c:set_context() Attempting to autoconfigure settings
Apr 23 08:40:18.322789 pureos mmsdtng[748]: ../src/service-providers.c:mmsd_service_providers_find_settings() mccmnc: 23207, apn: webaut
Apr 23 08:40:18.322972 pureos mmsdtng[748]: ../plugins/modemmanager.c:set_context() Current Context APN: webaut, mmsd-tng settings MMS APN: apn.invalid
Apr 23 08:40:18.323011 pureos mmsdtng[748]: ../plugins/modemmanager.c:set_context() The modem is not connected to the correct APN!
Apr 23 08:40:18.323036 pureos mmsdtng[748]: ../plugins/modemmanager.c:bearer_handler() Set MMSC: http://mms.invalid, Set Proxy: (null), Set MMS APN: apn.invalid
Apr 23 08:40:18.323614 pureos mmsdtng[748]: ../plugins/modemmanager.c:bearer_handler() At Bearer Handler: path /org/freedesktop/ModemManager1/Modem/7 active 1 context_active 0
Apr 23 08:40:18.323642 pureos mmsdtng[748]: ../plugins/modemmanager.c:bearer_handler() Error activating context!
Apr 23 08:40:18.323669 pureos mmsdtng[748]: ../src/service.c:mms_service_bearer_notify() service=0xaaaaea6c1cf0 active=0 iface=(null) proxy=(null)
Apr 23 08:40:18.326638 pureos chatty[1128]: Bearer Handler emitted an error, the APN set in mmsd's settings does not match any connected APNs
Apr 23 08:40:18.380135 pureos mmsdtng[748]: Could not find settings: Operator ID '23207' not found in service provider database
Apr 23 08:40:18.380183 pureos mmsdtng[748]: Your MMS settings are not in the database! Please file a merge request at https://gitlab.gnome.org/GNOME/mobile-broadband-provider-info so they can be added
Apr 23 08:40:21.750279 pureos goa-daemon[816]: /org/gnome/OnlineAccounts/Accounts/account_1638277513_0: Setting AttentionNeeded to FALSE because EnsureCredentials() succeded
Apr 23 08:40:22.313948 pureos mmsdtng[748]: ../plugins/modemmanager.c:mmsd_mm_get_messaging_list() Searching for all SMS
Apr 23 08:40:25.417330 pureos systemd[730]: tracker-extract.service: Succeeded.
Apr 23 08:40:28.390580 pureos systemd[1]: NetworkManager-dispatcher.service: Succeeded.
Apr 23 08:40:38.621863 pureos kernel: usb 1-1.2: usb auto-suspend, wakeup 1 - usbmon timestamp: 2337251133
Apr 23 08:40:38.641795 pureos kernel: usb 1-1.2: usb auto-resume - usbmon timestamp: 2337268392
Apr 23 08:40:38.709825 pureos kernel: usb 1-1.2: Waited 0ms for CONNECT
Apr 23 08:40:38.711711 pureos kernel: usb 1-1.2: finish resume