Date: Fri, 05 Dec 2008 16:38:11 -0500 From: Mike Tancsa <mike@sentex.net> To: Hans Petter Selasky <hselasky@c2i.net>, freebsd-usb@freebsd.org Subject: Re: ucom serial bug? Message-ID: <200812052138.mB5LcId3024797@lava.sentex.ca> In-Reply-To: <7.1.0.9.0.20081204172610.16c1d868@sentex.net> References: <200812041853.35539.hselasky@c2i.net> <49382D74.1030907@sentex.net> <49385176.3070104@sentex.net> <200812042320.48818.hselasky@c2i.net> <7.1.0.9.0.20081204172610.16c1d868@sentex.net>
next in thread | previous in thread | raw e-mail | index | archive | help
At 05:37 PM 12/4/2008, Mike Tancsa wrote:
>At 05:20 PM 12/4/2008, Hans Petter Selasky wrote:
>>On Thursday 04 December 2008, Gabor wrote:
>> > Some more twists to this. As I said if I kill off our program and restart
>> > it, it never sees carrier unless the module was reloaded. However, if I
>> > unplug the serial cable from the Windows box and re-plug it, carrier goes
>> > and comes back as expected but only as long as our software is
>> running. If
>> > our software is not running and we unplug the serial cable from
>> the Windows
>> > box, carrier does not come back when we start up our program
>> with the cable
>> > plugged back in.
>>
>>Maybe you can try setting the MSR to zero when the modem is opened in the
>>uftdi.c driver file.
>>
>>In USB2 there is also a sysctl for UFTDI debugging which you can check.
>
>Hi,
> In the regular USB stack, I did run it with some debugging
> enabled. The diff between the first run and the second run is
> below using Gabor's check carrier program
>
>I havent tried with debugging enabled and just pulling the serial
>cable out yet. I will try that tomorrow when back at the office!
While the program is running and has /dev/cuaU0 open and NOT seeing
carrier (when it should) its just a series of
Dec 5 15:56:50 current kernel: ucomstartread: start
Dec 5 15:56:50 current kernel: ucomreadcb: status = 0
Dec 5 15:56:50 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:50 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:50 current kernel: ucomstartread: start
with 4 ioctls in a 1 second span
# grep 15:56:50 all.log | grep ioc
Dec 5 15:56:50 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:50 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:50 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:50 current kernel: ucomioctl: cmd = 0x4004746a
When I go and unplug the serial cable and then plug it back in
I see
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: uftdi_read: status change
msr=0x20(0x00) lsr=0x60(0x60)
Dec 5 15:56:52 current kernel: uftdi_status: msr=0x20 lsr=0x60
Dec 5 15:56:52 current kernel: ucom_status_change: DCD changed to 1
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: uftdi_read: status change
msr=0xa0(0x20) lsr=0x60(0x60)
Dec 5 15:56:52 current kernel: uftdi_status: msr=0xa0 lsr=0x60
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:52 current kernel: ucomtty_outwakeup: sc = 0xc4568d80
Dec 5 15:56:52 current kernel: uftdi_write: sc=0xc4568d80, port=1
tp=0xc4d19000, count=64
Dec 5 15:56:52 current kernel: ucomtty_outwakeup: 3 chars
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:52 current kernel: ucomwritecb: status = 0
Dec 5 15:56:52 current kernel: ucomwritecb: cc = 3
Dec 5 15:56:52 current kernel: ucomtty_outwakeup: sc = 0xc4568d80
Dec 5 15:56:52 current kernel: uftdi_write: sc=0xc4568d80, port=1
tp=0xc4d19000, count=64
Dec 5 15:56:52 current kernel: ucomtty_outwakeup: cnt == 0
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: uftdi_read: status change
msr=0xb0(0xa0) lsr=0x60(0x60)
Dec 5 15:56:52 current kernel: uftdi_status: msr=0xb0 lsr=0x60
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 3 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=3
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1
count=3 data[0]=0x84
Dec 5 15:56:52 current kernel: ucomreadcb: char = 0x84
Dec 5 15:56:52 current kernel: ucomstartread: start
Dec 5 15:56:52 current kernel: ucomreadcb: status = 0
Dec 5 15:56:52 current kernel: ucomreadcb: got 2 chars, tp = 0xc4d19000
Dec 5 15:56:52 current kernel: uftdi_read: sc=0xc4568d80, port=1 count=2
Dec 5 15:56:52 current kernel: uftdi_read: status change
msr=0xa0(0xb0) lsr=0x60(0x60)
Dec 5 15:56:52 current kernel: uftdi_status: msr=0xa0 lsr=0x60
Dec 5 15:56:52 current kernel: ucomstartread: start
# grep "15:56:5[1-4]" all.log | grep ioc
Dec 5 15:56:51 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:51 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:51 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:51 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:52 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:53 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x2000745e
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x4004746a
Dec 5 15:56:54 current kernel: ucomioctl: cmd = 0x2000745e
Any ideas ?
---Mike
>In terms of setting the MSR to zero, do you mean in
>
>static int uftdi_open(void *vsc, int portno)
>
>?
>
>
>
>
>First run where the program sees carrier
>
>: ucom0 on uhub3
>: ucomtty_param: sc = 0xc47faa80
>: ucomstopread: enter
>: ucomstopread: bulkin pipe NULL
>: uftdi_param: sc=0xc47faa80
>: ucomstartread: start
>: ucom_dtr: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=1
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: ucom0: ucomtty_open: tp = 0xc4c7c800
>: ucom_dtr: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=1
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: uftdi_open: sc=0xc47faa80
>: uftdi_param: sc=0xc47faa80
>: ucomtty_open: open pipes in = 129 out = 2
>: ucomstartread: start
>: ucomioctl: cmd = 0x402c7413
>: ucomioctl: cmd = 0x802c7414
>: ucomtty_param: sc = 0xc47faa80
>: ucomstopread: enter
>: ucomreadcb: status = 6
>: ucomstopread: leave
>: uftdi_param: sc=0xc47faa80
>: ucomstartread: start
>: ucomioctl: cmd = 0x8004667e
>: ucomioctl: cmd = 0x8004667d
>: ucomioctl: cmd = 0x4004746a
>: ucomioctl: cmd = 0x4004746a
>: ucomioctl: cmd = 0x8004746d
>: ucom_dtr: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=1
>: ucomreadcb: status = 0
>: ucomreadcb: got 2 chars, tp = 0xc4c7c800
>: uftdi_read: status change msr=0xb0(0x00) lsr=0x60(0x00)
>: uftdi_status: msr=0xb0 lsr=0x60
>: ucom_status_change: about to check sc->sc_poll it is 1
>: ucom_status_change: DCD changed to 1
>: ucomstartread: start
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: ucomioctl: cmd = 0x4004746a
>: ucom0: ucomtty_close
>: ucom_cleanup: closing pipes
>: ucom_shutdown
>: ucom_dtr: onoff = 0
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=0
>: ucomreadcb: status = 0
>: ucomreadcb: got 2 chars, tp = 0xc4c7c800
>: uftdi_read: status change msr=0x00(0xb0) lsr=0x60(0x60)
>: uftdi_status: msr=0x00 lsr=0x60
>: ucom_status_change: about to check sc->sc_poll it is 1
>: ucom_status_change: DCD changed to 0
>: ucomstartread: start
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: ucomreadcb: status = 0
>: ucomreadcb: got 2 chars, tp = 0xc4c7c800
>: uftdi_read: status change msr=0xb0(0x00) lsr=0x60(0x60)
>: uftdi_status: msr=0xb0 lsr=0x60
>: ucom_status_change: about to check sc->sc_poll it is 1
>: ucom_status_change: DCD changed to 1
>: ucomstartread: start
>: ucomreadcb: status = 6
>
>and second run, where it does not
>
>
>
>: ucomtty_param: sc = 0xc47faa80
>: ucomstopread: enter
>: ucomstopread: leave
>: uftdi_param: sc=0xc47faa80
>: ucomstartread: start
>: ucom_dtr: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=1
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: ucom0: ucomtty_open: tp = 0xc4c7c800
>: ucom_dtr: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=1
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: uftdi_open: sc=0xc47faa80
>: uftdi_param: sc=0xc47faa80
>: ucomtty_open: open pipes in = 129 out = 2
>: ucomstartread: start
>: ucomioctl: cmd = 0x402c7413
>: ucomioctl: cmd = 0x802c7414
>: ucomtty_param: sc = 0xc47faa80
>: ucomstopread: enter
>: ucomreadcb: status = 6
>: ucomstopread: leave
>: uftdi_param: sc=0xc47faa80
>: ucomstartread: start
>: ucomioctl: cmd = 0x8004667e
>: ucomioctl: cmd = 0x8004667d
>: ucomioctl: cmd = 0x4004746a
>: ucomioctl: cmd = 0x4004746a
>: ucomioctl: cmd = 0x8004746d
>: ucom_dtr: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=1
>: ucomreadcb: status = 0
>: ucomreadcb: got 2 chars, tp = 0xc4c7c800
>: ucomstartread: start
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: ucomioctl: cmd = 0x4004746a
>: ucom0: ucomtty_close
>: ucom_cleanup: closing pipes
>: ucom_shutdown
>: ucom_dtr: onoff = 0
>: uftdi_set: sc=0xc47faa80, port=1 reg=1 onoff=0
>: ucomreadcb: status = 0
>: ucomreadcb: got 2 chars, tp = 0xc4c7c800
>: uftdi_read: status change msr=0x00(0xb0) lsr=0x60(0x60)
>: uftdi_status: msr=0x00 lsr=0x60
>: ucomstartread: start
>: ucom_rts: onoff = 1
>: uftdi_set: sc=0xc47faa80, port=1 reg=2 onoff=1
>: ucomreadcb: status = 0
>: ucomreadcb: got 2 chars, tp = 0xc4c7c800
>: uftdi_read: status change msr=0xb0(0x00) lsr=0x60(0x60)
>: uftdi_status: msr=0xb0 lsr=0x60
>: ucom_status_change: about to check sc->sc_poll it is 1
>: ucom_status_change: DCD changed to 1
>: ucomstartread: start
>: ucomreadcb: status = 6
>
>
>
>
>% diff a b
>2d1
>< : ucom0 on uhub3
>5c4
>< : ucomstopread: bulkin pipe NULL
>---
> > : ucomstopread: leave
>38,41d36
>< : uftdi_read: status change msr=0xb0(0x00) lsr=0x60(0x00)
>< : uftdi_status: msr=0xb0 lsr=0x60
>< : ucom_status_change: about to check sc->sc_poll it is 1
>< : ucom_status_change: DCD changed to 1
>55,56d49
>< : ucom_status_change: about to check sc->sc_poll it is 1
>< : ucom_status_change: DCD changed to 0
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200812052138.mB5LcId3024797>