2005-11-23 21:25:22

by Alistair John Strachan

[permalink] [raw]
Subject: speedtch driver, 2.6.14.2

Hi Duncan,

I recently switched from the userspace speedtouch driver to the in-kernel one.
However, on my rev 4.0 Speedtouch 330, I periodically get the message:

ATM dev 0: error -110 fetching device status

I suspect the source of this "error" is the warning message from speedtch:435:

ret = speedtch_read_status(instance);
if (ret < 0) {
atm_warn(usbatm, "error %d fetching device status\n", ret);
instance->poll_delay = min(2 * instance->poll_delay, MAX_POLL_DELAY);
return;
}

Tell me if I'm wrong, but I suspect speedtch_check_status() is called
periodically to check line status. It may be the case that my modem does not
like having its status read when it is sending/receiving data (which it is
constantly doing).

Unfortunately the message eventually fills the dmesg ring buffer. My current
workaround is to remove the atm_warn() call; everything works fine, but I'm
concerned that the modem will not automatically reconnect if the connection
drops as a result of the failure from speedtch_read_status().

Any suggestions for debugging this further? From a quick google I've noticed a
recent Fedora bugzilla entry mentioning this same problem.

--
Cheers,
Alistair.

'No sense being pessimistic, it probably wouldn't work anyway.'
Third year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.


2005-11-24 08:23:07

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Hi Alistair,

> I recently switched from the userspace speedtouch driver to the in-kernel one.
> However, on my rev 4.0 Speedtouch 330, I periodically get the message:
>
> ATM dev 0: error -110 fetching device status

-110 means that it timed out.

> I suspect the source of this "error" is the warning message from speedtch:435:
>
> ret = speedtch_read_status(instance);
> if (ret < 0) {
> atm_warn(usbatm, "error %d fetching device status\n", ret);
> instance->poll_delay = min(2 * instance->poll_delay, MAX_POLL_DELAY);
> return;
> }
>
> Tell me if I'm wrong, but I suspect speedtch_check_status() is called
> periodically to check line status. It may be the case that my modem does not
> like having its status read when it is sending/receiving data (which it is
> constantly doing).

Well, I have the same modem, and mine doesn't seem to mind! So something is
strange.

> Unfortunately the message eventually fills the dmesg ring buffer. My current
> workaround is to remove the atm_warn() call; everything works fine, but I'm
> concerned that the modem will not automatically reconnect if the connection
> drops as a result of the failure from speedtch_read_status().

You can test it by unplugging the phone line, then replugging it.

> Any suggestions for debugging this further? From a quick google I've noticed a
> recent Fedora bugzilla entry mentioning this same problem.

I'll think about it.

All the best,

Duncan.

2005-11-24 17:01:15

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

> I recently switched from the userspace speedtouch driver to the in-kernel one.
> However, on my rev 4.0 Speedtouch 330, I periodically get the message:
>
> ATM dev 0: error -110 fetching device status

By the way, did you use to monitor the line using modem_run? Did it work
(and of course: did you get any error messages?).

Ciao,

D.

2005-11-26 23:48:23

by Alistair John Strachan

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

On Thursday 24 November 2005 17:01, Duncan Sands wrote:
> > I recently switched from the userspace speedtouch driver to the in-kernel
> > one. However, on my rev 4.0 Speedtouch 330, I periodically get the
> > message:
> >
> > ATM dev 0: error -110 fetching device status
>
> By the way, did you use to monitor the line using modem_run? Did it work
> (and of course: did you get any error messages?).

I don't use modem_run any more, but when I did (with the userspace driver), I
would not get any errors whatsoever. It didn't reconnect automatically,
however.

I'll try enabling USB_DEBUG next time I upgrade that machine's kernel.
Unfortunately I don't have access to it at the moment (but will within the
week).

Thanks for the help so far!

--
Cheers,
Alistair.

'No sense being pessimistic, it probably wouldn't work anyway.'
Third year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.

2005-11-27 22:58:34

by Krzysztof Halasa

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Alistair John Strachan <[email protected]> writes:

> However, on my rev 4.0 Speedtouch 330, I periodically get the message:
>
> ATM dev 0: error -110 fetching device status

Same here.

defiant:~$ dmesg | grep 'ATM dev 0: error -110 fetching device status' | wc -l
55
defiant:~$ uptime
23:55:40 up 15 days, 23:34, 6 users, load average: 0.05, 0.06, 0.06

It works fine, though.
--
Krzysztof Halasa

2005-11-28 08:29:54

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

On Sunday 27 November 2005 23:58, Krzysztof Halasa wrote:
> Alistair John Strachan <[email protected]> writes:
>
> > However, on my rev 4.0 Speedtouch 330, I periodically get the message:
> >
> > ATM dev 0: error -110 fetching device status
>
> Same here.
>
> defiant:~$ dmesg | grep 'ATM dev 0: error -110 fetching device status' | wc -l
> 55
> defiant:~$ uptime
> 23:55:40 up 15 days, 23:34, 6 users, load average: 0.05, 0.06, 0.06
>
> It works fine, though.

If you unplug the phone line and plug it back in again, does the line
resynchronize? Does the driver detect that the line is back up?

Thanks,

D.

2005-11-28 10:04:12

by Krzysztof Halasa

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Duncan Sands <[email protected]> writes:

> If you unplug the phone line and plug it back in again, does the line
> resynchronize? Does the driver detect that the line is back up?

Sure.
--
Krzysztof Halasa

2005-11-28 11:34:48

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

> > If you unplug the phone line and plug it back in again, does the line
> > resynchronize? Does the driver detect that the line is back up?
>
> Sure.

If you turn on CONFIG_USB_DEBUG, enough info should turn up to be able
to work out which urbs are failing. That would be helpful.

Ciao,

D.

2005-11-28 11:44:34

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Which firmware are you using?

D.

2005-11-28 17:18:20

by Krzysztof Halasa

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Duncan Sands <[email protected]> writes:

> If you turn on CONFIG_USB_DEBUG, enough info should turn up to be able
> to work out which urbs are failing. That would be helpful.

dmesg | egrep -i 'usb|atm|speedt' attached.

Firmware? Didn't know I have options :-)
I think it's version 3.012, I got it with ADSL subscriber package
and extracted using (probably) the firmware extractor (the hacked
modem_run). I can verify this if you want.

935 Nov 27 2004 speedtch-1.bin.4.00
775545 Nov 27 2004 speedtch-2.bin.4.00

MD5:
0503efe8d7efc0fe10e7593cecdb8fb8 speedtch-1.bin.4.00
79300e856fbef976c99fe339be8ba238 speedtch-2.bin.4.00

defiant:/lib/firmware$ cat /proc/bus/usb/devices |grep -B 1 TH
P: Vendor=06b9 ProdID=4061 Rev= 4.00
S: Manufacturer=THOMSON


15:54:29 USB Universal Host Controller Interface driver v2.3
15:54:31 uhci_hcd 0000:00:07.2: new USB bus registered, assigned bus number 1
15:54:31 usb usb1: default language 0x0409
15:54:31 usb usb1: new device strings: Mfr=3, Product=2, SerialNumber=1
15:54:31 usb usb1: Product: UHCI Host Controller
15:54:31 usb usb1: Manufacturer: Linux 2.6.14 uhci_hcd
15:54:31 usb usb1: SerialNumber: 0000:00:07.2
15:54:31 usb usb1: hotplug
15:54:31 usb usb1: adding 1-0:1.0 (config #1, interface 0)
15:54:31 usb 1-0:1.0: hotplug
15:54:31 hub 1-0:1.0: usb_probe_interface
15:54:31 hub 1-0:1.0: usb_probe_interface - got id
15:54:31 hub 1-0:1.0: USB hub found
15:54:31 hub 1-0:1.0: no power switching (usb 1.0)
15:54:32 usb 1-1: new full speed USB device using uhci_hcd and address 2
15:54:32 usb 1-1: ep0 maxpacket = 8
15:54:32 usb 1-1: default language 0x0409
15:54:32 usb 1-1: new device strings: Mfr=1, Product=2, SerialNumber=3
15:54:32 usb 1-1: Product: Speed Touch 330
15:54:32 usb 1-1: Manufacturer: THOMSON
15:54:32 usb 1-1: SerialNumber: 000E501A7727
15:54:32 usb 1-1: hotplug
15:54:32 usb 1-1: adding 1-1:1.0 (config #1, interface 0)
15:54:32 usb 1-1:1.0: hotplug
15:54:32 usb 1-1: adding 1-1:1.1 (config #1, interface 1)
15:54:32 usb 1-1:1.1: hotplug
15:54:32 usb 1-1: adding 1-1:1.2 (config #1, interface 2)
15:54:32 usb 1-1:1.2: hotplug
15:54:32 Initializing USB Mass Storage driver...
15:54:33 usbcore: registered new driver usb-storage
15:54:33 USB Mass Storage support registered.
15:54:33 usbatm.c: usbatm_usb_init: driver version 1.9
15:54:33 speedtch.c: speedtch_usb_init: driver version 1.9
15:54:33 speedtch 1-1:1.0: usb_probe_interface
15:54:33 speedtch 1-1:1.0: usb_probe_interface - got id
15:54:33 speedtch 1-1:1.0: usbatm_usb_probe: trying driver speedtch with
vendor=0x6b9, product=0x4061, ifnum 0
15:54:33 usb 1-1: modprobe timed out on ep0in len=0/1
15:54:33 usb 1-1: reset full speed USB device using uhci_hcd and address 2
15:54:33 usb 1-1: ep0 maxpacket = 8
15:54:33 usbcore: registered new driver speedtch
15:54:33 speedtch 1-1:1.0: found stage 1 firmware speedtch-1.bin.4.00
15:54:33 speedtch 1-1:1.0: found stage 2 firmware speedtch-2.bin.4.00
15:54:34 ATM dev 0: speedtch_atm_start entered
15:54:34 ATM dev 0: speedtch_start_synchro entered
15:54:34 ATM dev 0: speedtch_start_synchro: modem prodded. 2 bytes returned: 00
00
15:54:34 /usr/src/linux-2.6/drivers/usb/atm/usbatm.c: usbatm_get_instance
15:54:34 ATM dev 0: speedtch_check_status entered
15:54:34 ATM dev 0: speedtch_check_status: line state 10
15:54:34 ATM dev 0: ADSL line is synchronising
15:54:34 ATM dev 0: usbatm_atm_open: vpi 0, vci 35
15:54:34 ATM dev 0: usbatm_atm_open: allocated vcc data 0xc7e03be0
15:54:34 ATM dev 0: speedtch_check_status entered
15:54:34 ATM dev 0: speedtch_check_status: line state 10
15:54:34 ATM dev 0: speedtch_check_status entered
15:54:34 ATM dev 0: speedtch_check_status: line state 10
15:54:34 ATM dev 0: speedtch_check_status entered
15:54:34 ATM dev 0: speedtch_check_status: line state 20
15:54:34 ATM dev 0: ADSL line is up (320 kb/s down | 160 kb/s up)
15:54:34 ATM dev 0: speedtch_check_status entered
15:54:34 ATM dev 0: speedtch_check_status: line state 20
15:54:35 ATM dev 0: speedtch_check_status entered
15:54:35 ATM dev 0: speedtch_check_status: line state 20
15:54:40 ATM dev 0: speedtch_check_status entered
15:54:40 ATM dev 0: speedtch_check_status: line state 20

(and so on)

17:03:10 ATM dev 0: speedtch_check_status entered
17:03:10 ATM dev 0: speedtch_check_status: line state 20
17:03:15 ATM dev 0: speedtch_check_status entered
17:03:17 usb 1-1: events/0 timed out on ep0in len=0/4
17:03:17 ATM dev 0: speedtch_read_status: MSG D failed
17:03:17 ATM dev 0: error -110 fetching device status
17:03:20 ATM dev 0: speedtch_check_status entered
17:03:20 ATM dev 0: speedtch_check_status: line state 20
--
Krzysztof Halasa

2005-11-29 11:14:09

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Hi Krzysztof, the firmware seems fine.

> 17:03:15 ATM dev 0: speedtch_check_status entered
> 17:03:17 usb 1-1: events/0 timed out on ep0in len=0/4
> 17:03:17 ATM dev 0: speedtch_read_status: MSG D failed
> 17:03:17 ATM dev 0: error -110 fetching device status

Is it always MSG D that fails? Is failure of this message
correlated with anything else, eg: heavy network use?

Thanks,

Duncan.

2005-11-29 12:46:59

by Krzysztof Halasa

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Hi,

Duncan Sands <[email protected]> writes:

>> 17:03:15 ATM dev 0: speedtch_check_status entered
>> 17:03:17 usb 1-1: events/0 timed out on ep0in len=0/4
>> 17:03:17 ATM dev 0: speedtch_read_status: MSG D failed
>> 17:03:17 ATM dev 0: error -110 fetching device status
>
> Is it always MSG D that fails?

I think so. Since yesterday I have 7 identical MSG D faults and nothing
else.

> Is failure of this message
> correlated with anything else, eg: heavy network use?

I don't think so. The ADSL was mostly idle last 24 hrs. Only inbound SMTP
mail and the Windows viruses etc. trying to attack something.

I can perform a test with inactive PPP (=no any flow) but I think it will
show up the same.

BTW: it's an old notebook PC, i440BX (PIIX4) based:

00:00.0 Host bridge: Intel 440BX/ZX/DX - 82443BX/ZX/DX Host bridge (rev 03)
00:01.0 PCI bridge: Intel 440BX/ZX/DX - 82443BX/ZX/DX AGP bridge (rev 03)
00:07.0 ISA bridge: Intel 82371AB/EB/MB PIIX4 ISA (rev 02)
00:07.1 IDE interface: Intel 82371AB/EB/MB PIIX4 IDE (rev 01)
00:07.2 USB Controller: Intel 82371AB/EB/MB PIIX4 USB (rev 01)
00:07.3 Bridge: Intel 82371AB/EB/MB PIIX4 ACPI (rev 03)
00:0a.0 CardBus bridge: Texas Instruments PCI1225 (rev 01)
00:0a.1 CardBus bridge: Texas Instruments PCI1225 (rev 01)
00:0d.0 ESS Technology ES1983S Maestro-3i PCI Audio Accelerator
00:0d.1 ESS Technology ES1983S Maestro-3i PCI Modem Accelerator
01:00.0 VGA: Silicon Motion, Inc. SM720 Lynx3DM (rev b1)
02:00.0 Ethernet: DECchip 21142/43 (rev 41)
--
Krzysztof Halasa

2005-12-01 07:59:20

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

> ... Since yesterday I have 7 identical MSG D faults and nothing
> else.

Does increasing the value of CTRL_TIMEOUT help?

D.

2005-12-01 15:17:54

by Krzysztof Halasa

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Duncan Sands <[email protected]> writes:

>> ... Since yesterday I have 7 identical MSG D faults and nothing
>> else.
>
> Does increasing the value of CTRL_TIMEOUT help?

I've increased it to 4 seconds, no change. It looks like the response
(or request) is lost somewhere.

The answer is always the same second:

Dec 1 15:20:32 defiant kernel: ATM dev 0: speedtch_check_status entered
Dec 1 15:20:32 defiant kernel: ATM dev 0: speedtch_check_status: line state 20
Dec 1 15:20:37 defiant kernel: ATM dev 0: speedtch_check_status entered
Dec 1 15:20:37 defiant kernel: ATM dev 0: speedtch_check_status: line state 20
Dec 1 15:20:42 defiant kernel: ATM dev 0: speedtch_check_status entered
Dec 1 15:20:42 defiant kernel: ATM dev 0: speedtch_check_status: line state 20

... or it doesn't come at all:

Dec 1 15:20:47 defiant kernel: ATM dev 0: speedtch_check_status entered
Dec 1 15:20:51 defiant kernel: usb 1-1: events/0 timed out on ep0in len=0/4
Dec 1 15:20:51 defiant kernel: ATM dev 0: speedtch_read_status: MSG D failed
Dec 1 15:20:51 defiant kernel: ATM dev 0: error -110 fetching device status

Do the speedtouches have some means (firmware) for debugging or logging?
We would need to see what does the ADSL receive and what does it think
about it.
--
Krzysztof Halasa

2005-12-01 15:19:55

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

> Do the speedtouches have some means (firmware) for debugging or logging?
> We would need to see what does the ADSL receive and what does it think
> about it.

I don't even have any specs...

D.

2005-12-01 16:14:22

by Krzysztof Halasa

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Duncan Sands <[email protected]> writes:

>> Do the speedtouches have some means (firmware) for debugging or logging?
>> We would need to see what does the ADSL receive and what does it think
>> about it.
>
> I don't even have any specs...

"strings" on the fw binary shows there is some debugger (SACHEM-LT and
possibly more things). It probably needs some terminal interface,
there might be some diagnostic port (usually TTL-level RS232) on board
or (in this case almost certainly) it's created over USB.

It would require some amount of work, not sure if it's worth it.
--
Krzysztof Halasa

2005-12-02 16:46:21

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

Hi Krzysztof,

> Dec 1 15:20:47 defiant kernel: ATM dev 0: speedtch_check_status entered
> Dec 1 15:20:51 defiant kernel: usb 1-1: events/0 timed out on ep0in len=0/4
> Dec 1 15:20:51 defiant kernel: ATM dev 0: speedtch_read_status: MSG D failed
> Dec 1 15:20:51 defiant kernel: ATM dev 0: error -110 fetching device status

by an amazing coincidence, exactly the same thing happened to me yesterday. I
had plugged and unplugged the phone line several times during the day, so maybe
I will be able to reproduce it at will.

Ciao,

Duncan.

2006-01-13 12:16:00

by Duncan Sands

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

> I recently switched from the userspace speedtouch driver to the in-kernel one.
> However, on my rev 4.0 Speedtouch 330, I periodically get the message:
>
> ATM dev 0: error -110 fetching device status

Is this correlated with disk activity (heavy use of the pci bus)?

Thanks,

Duncan.

2006-01-13 13:33:40

by Andrew Walrond

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

On Friday 13 January 2006 12:15, Duncan Sands wrote:
> > I recently switched from the userspace speedtouch driver to the in-kernel
> > one. However, on my rev 4.0 Speedtouch 330, I periodically get the
> > message:
> >
> > ATM dev 0: error -110 fetching device status

Me too.

log-2005-12-08-08:39:10:Dec 5 04:34:34 [kernel] ATM dev 0: error -110
fetching device status
log-2005-12-31-24:59:59:Dec 14 18:17:59 [kernel] ATM dev 0: error -110
fetching device status
current:Jan 12 11:32:33 [kernel] ATM dev 0: error -110 fetching device status

So it happens every two/three weeks. I have to reboot to get the ADSL line
back up.

>
> Is this correlated with disk activity (heavy use of the pci bus)?
>

Not here. This is an essentially idle mail server, using ADSL as backup net
connection.

$ uptime
13:26:09 up 17:08, 0 users, load average: 0.01, 0.01, 0.00

$ uname -a
Linux pelagius.h-e-r-e-s-y.com 2.6.14.2 #1 SMP PREEMPT Sat Nov 12 21:01:17 GMT
2005 i686 unknown unknown GNU/Linux

I guess people running desktops rarely notice the problem, since they are
likely to power cycle more frequently than the error occurs. For long lived
servers, its quite a nuisance.

Let me know if I can do anything to help track this down. I'm happy to run an
instrumented kernel if that would help.

Andrew Walrond

2006-01-13 19:08:16

by Alistair John Strachan

[permalink] [raw]
Subject: Re: speedtch driver, 2.6.14.2

On Friday 13 January 2006 12:15, Duncan Sands wrote:
> > I recently switched from the userspace speedtouch driver to the in-kernel
> > one. However, on my rev 4.0 Speedtouch 330, I periodically get the
> > message:
> >
> > ATM dev 0: error -110 fetching device status
>
> Is this correlated with disk activity (heavy use of the pci bus)?

No, the machine is completely idle. However I switched to the CVS driver (it
does not work in isochronous mode still), and in bulk-mode it gives me a new
set of messages:

ATM dev 0: speedtch_read_status: MSG E failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG F failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG F failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG D failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG D failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG D failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG B failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG B failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG B failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG F failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG F failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG B failed
ATM dev 0: error -110 fetching device status
ATM dev 0: speedtch_read_status: MSG F failed
ATM dev 0: error -110 fetching device status

This seems to happen less often than with the kernel driver, however.

--
Cheers,
Alistair.

'No sense being pessimistic, it probably wouldn't work anyway.'
Third year Computer Science undergraduate.
1F2 55 South Clerk Street, Edinburgh, UK.