problems with wvdial
in [Linux Networking]
|
Prev: Debian installed - Now what?
Next: Very strange, multiple IP addresses on the same Ethernet card donot route properly
From: lrhorer on 18 Jan 2010 18:38 >>> No I'm not sure, hence the "I believe" part. It could also require >>> an ioctl or some other special operation. What happens if you remove >>> [eou]hci-hcd (the USB port driver)? >> >> Nothing at all, I think. I believe the device has to be >> commanded to >> down the port (and I believe it is port specific). I also have to >> qualify the statement with "I believe", because that just what the >> reading I have done and the people to whom I have spoken so far has >> suggested. One of the USB gurus tho whom I have spoken (Alan Stern >> at Harvard) has suggested the best way to approach the issue is to >> unbind the driver and then issue the command to shut down power on >> the port. That makes me think unbinding the driver isn't sufficient >> by itself. > > linux/Documentation/usb/power-management.txt My system does not have that file. I found a copy on the web. > Though I don't see any files except wakeup in the power > sub-directories when I look. Could be my Aspire 1 ports don't support > power management, or I didn't have the necessary options set when I > built the kernel. > I was going to suggest LKML, but if you're already corresponding with > Alan Stern that's superfulous. Did he suggest usbmon? No, he did not. > That shows the > USB bus transactions which might help. > The problem could actually be a "feature" of the device, perhaps to > save power or eliminate the stupid dance to "safely remove hardware" > in Windows. The Windows program could "know" how to reactivate the > device. 'Doesn't seem to be. Lockups are random. >>> Also there's additional debugging info that can be turned on for >>> USB. I think it's a kernel config option though. >>> >>>>> As for "interfacing the router's control scripts with the dialing >>>>> utility": chat. >>>> >>>> That seems to be the consensus. >>> >>> Yep, there's a good reason for that: flexibilty and control. I still >>> use dial-up when I visit my dad in Florida. I have a bash script >>> which builds the chat script (dependent on the modem & some >>> options), then invokes pppd with the connect option to actually do >>> anything. >>> >>> Also 2.6.26 is an old kernel (late 2008), current stable is >>> 2.6.32.3. >> >> Debian never packages the most recent versions of software, >> unless the >> release affects security or addresses a significant bug. It is an >> extremely conservative distribution, which is the main reason I use >> it. It definitely never has all the new bells and whistles, and it >> isn't for someone who wants to always have support for all the latest >> gadgets, but it is rock solid and provides new meaning for the >> term "stable". I use it on all my servers, and I am using it on this >> router in large measure because it is stable in the extreme. Most >> distros have maybe two versions, Stable and Unstable. Debian has >> Stable, Unstable, Testing, and Experimental, in order of decreasing >> reliability. What most distros call, "Stable", Debian calls >> "Testing". >> If you ask me, late 2008 isn't all that "old". A lot of bugs can go >> undetected after only a little more than 1 year in public release. >> If I need anything from one of the newer kernels, I can always >> download and compile it, but there's nothing from any of the newer >> kernels that >> is missing in 2.6.26 and that I need for this project. Indeed, I >> suspect I may never upgrade the kernel, or anything else, on this >> machine once it is permanently online. Its job is just to sit on the >> shelf, route packets, generate a firewall, provide DHCP support, and >> provide a VPN tunnel into my file server at my house. > > Except that getting support for a year old kernel via LKML is likely > to be difficult. I'm surprised Alan Stern didn't suggest upgrading. No, he just pointed out why it could be problematical in general.
From: lrhorer on 18 Jan 2010 22:25 >>> You actually do not have debugging switched on for your pppd (option >>> debug to pppd) >> >> Yes, I do. The debug directive is in the options file. > > Good. But what you display is NOT the pppd debug logs. Then pppd isn't creating them, unless it is someplace other than /var/log/. The debug option is in the options file, as I mentioned. > Did you put the line > daemon.*;local2.* /var/log/daemonlog I already responded to that. I did not have to. It was already there. > (or whereever you want to put it) into /etc/syslog.conf, and restart > syslog.conf > killall -1 syslogd Again, as I already mentioned, this isn't necessary. The router has been both cold and warm booted many, many times, and the logging parameters were already there when the system was created. Oh, and just BTW, this distro does not use syslog.d. It's using rsyslog.d. not that ity really matters. > Have you looked into /var/log/deamonlog ( or whereever you want to put > it) during that disconnect. /var/log/messages and /var/log/syslog are as shown above for the Jan 16 event. /var/log/daemon.log has been completely empty since Jan 15 20:44. There are no logs at all in daemon.log for ppp at any time going all the way back to Dec 27, although there are logs from ntpd concerning its listening and shutting down on ppp0. When the Jan 16 event took place, I was in the middle of writing the chat script for pppd and setting up pppd as the primary shell. I didn't make any changes to the options file, but after I started running pppd as the primary shell (not that it should make a difference), it started doing more verbose logging. There was a lock-up just an hour ago, although this time without a USB bus reset. I've enabled he persist option in pppd, at least for the time being. It does allow the system to recover from an ordinary idle time-out. This event did not involve a USB reset, /dev/ACM0 stayed online, and the modem was able to respond to AT commands. It would not dial, however, either using pppd or minicom. The first response to a simgle AT command was "ERROR" after I shut down pppd and ran minicom to do some manual testing. Here is the log from the event: Jan 18 18:29:54 Cricket pppd[5836]: No response to 4 echo-requests Jan 18 18:29:54 Cricket pppd[5836]: Serial link appears to be disconnected. Jan 18 18:29:54 Cricket pppd[5836]: Connect time 306.6 minutes. Jan 18 18:29:54 Cricket pppd[5836]: Sent 445560 bytes, received 588608 bytes. Jan 18 18:29:54 Cricket pppd[5836]: Script /etc/ppp/ip-down started (pid 10015) Jan 18 18:29:54 Cricket pppd[5836]: sent [LCP TermReq id=0x2 "Peer not responding"] Jan 18 18:29:54 Cricket pppd[5836]: Script /etc/ppp/ip-down finished (pid 10015), status = 0x0 Jan 18 18:29:57 Cricket pppd[5836]: sent [LCP TermReq id=0x3 "Peer not responding"] Jan 18 18:30:00 Cricket pppd[5836]: Connection terminated. Jan 18 18:31:56 Cricket pppd[5836]: ioctl(TIOCSETD, N_TTY): Interrupted system call (line 571) Jan 18 18:31:57 Cricket pppd[5836]: tcsetattr: Interrupted system call (line 1010) Jan 18 18:31:57 Cricket pppd[5836]: Hangup (SIGHUP) Jan 18 18:31:57 Cricket pppd[5836]: Modem hangup Jan 18 18:31:58 Cricket pppd[5836]: Hangup (SIGHUP) Jan 18 18:32:04 Cricket chat[10941]: Can't get terminal parameters: Input/output error Jan 18 18:32:04 Cricket pppd[5836]: Connect script failed Jan 18 18:32:04 Cricket pppd[5836]: Hangup (SIGHUP) Jan 18 18:32:54 Cricket ntpd[2516]: Deleting interface #13 ppp0, 10.100.37.231#123, interface stats: received=0, sent=0, dropped=0, active_time =18300 secs Jan 18 18:51:10 Cricket dnsmasq[2435]: reading /etc/resolv.conf Jan 18 18:51:10 Cricket dnsmasq[2435]: using nameserver 24.93.41.128#53 Jan 18 18:51:10 Cricket dnsmasq[2435]: using nameserver 24.93.41.127#53 Jan 18 18:51:10 Cricket dnsmasq[2435]: DHCPREQUEST(eth0) 192.168.1.77 00:1b:11:1a:2b:b0 Jan 18 18:51:10 Cricket dnsmasq[2435]: DHCPACK(eth0) 192.168.1.77 00:1b:11:1a:2b:b0 Brittany That's it. Pppd did not shut down, did not release the loackfile, and did not release /dev/ttyACM0. I shut down pppd with `kill -9`, and re-started it. After restart, it produced only a single line in syslog: Jan 18 19:07:17 Cricket pppd[30605]: pppd 2.4.4 started by root, uid 0 Again, it produced a lockfile and grabbed /dev/ttyACM0, but it did nit run the chat script or anything else. I killed pppd again, and ran minicom to see if the modem was responding on /dev/ttyACM0. It was. I pulled the modem and reseated it, running pppd, again: Jan 18 19:10:30 Cricket kernel: [52380.248072] usb 1-2: USB disconnect, address 3 Jan 18 19:10:44 Cricket kernel: [52394.364017] usb 1-2: new full speed USB device using uhci_hcd and address 4 Jan 18 19:10:44 Cricket kernel: [52394.527131] usb 1-2: configuration #1 chosen from 1 choice Jan 18 19:10:44 Cricket kernel: [52394.534360] scsi1 : SCSI emulation for USB Mass Storage devices Jan 18 19:10:44 Cricket kernel: [52394.541500] usb 1-2: New USB device found, idVendor=1f28, idProduct=0021 Jan 18 19:10:44 Cricket kernel: [52394.541513] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Jan 18 19:10:44 Cricket kernel: [52394.541518] usb 1-2: Product: USB Micro SD Storage Jan 18 19:10:44 Cricket kernel: [52394.541522] usb 1-2: Manufacturer: Cal-comp E&CC Limited Jan 18 19:10:44 Cricket kernel: [52394.541526] usb 1-2: SerialNumber: 214939913900 Jan 18 19:10:44 Cricket kernel: [52394.542908] usb-storage: device found at 4 Jan 18 19:10:44 Cricket kernel: [52394.542919] usb-storage: waiting for device to settle before scanning Jan 18 19:10:49 Cricket kernel: [52399.541264] usb-storage: device scan complete Jan 18 19:10:49 Cricket kernel: [52399.544176] scsi 1:0:0:0: Direct-Access Cricket T-Flash Disk 2.31 PQ: 0 ANSI: 2 Jan 18 19:10:49 Cricket kernel: [52399.544176] scsi 1:0:0:1: CD-ROM Cal-Comp CD INSTALLER 2.31 PQ: 0 ANSI: 0 Jan 18 19:10:49 Cricket kernel: [52399.592290] sd 1:0:0:0: [sda] Attached SCSI removable disk Jan 18 19:10:50 Cricket kernel: [52399.777931] Driver 'sr' needs updating - please use bus_type methods Jan 18 19:10:50 Cricket kernel: [52399.832120] sr0: scsi3-mmc drive: 0x/0x caddy Jan 18 19:10:50 Cricket kernel: [52399.832120] sr 1:0:0:1: Attached scsi CD-ROM sr0 Jan 18 19:10:50 Cricket kernel: [52399.918559] sd 1:0:0:0: Attached scsi generic sg0 type 0 Jan 18 19:10:50 Cricket kernel: [52399.918611] sr 1:0:0:1: Attached scsi generic sg1 type 5 Jan 18 19:10:50 Cricket kernel: [52400.039108] sr0: CDROM (ioctl) error, command: Get configuration 46 00 00 00 00 00 00 00 20 00 Jan 18 19:10:50 Cricket kernel: [52400.039131] sr: Sense Key : No Sense [current] Jan 18 19:10:50 Cricket kernel: [52400.039138] sr: Add. Sense: No additional sense information Jan 18 19:10:50 Cricket kernel: [52400.220020] usb 1-2: reset full speed USB device using uhci_hcd and address 4 Jan 18 19:10:50 Cricket kernel: [52400.488029] usb 1-2: reset full speed USB device using uhci_hcd and address 4 Jan 18 19:10:51 Cricket kernel: [52400.760032] usb 1-2: reset full speed USB device using uhci_hcd and address 4 Jan 18 19:11:03 Cricket pppd[31677]: unrecognized option '/dev/ttyACM0' I shut down the router altogether and rebooted: Cricket:/var/log# grep pppd syslog <snip> Jan 18 20:11:24 Cricket pppd[3062]: pppd 2.4.4 started by root, uid 0 Jan 18 20:11:25 Cricket pppd[3062]: Connect script failed Jan 18 20:12:03 Cricket pppd[3062]: Serial connection established. Jan 18 20:12:03 Cricket pppd[3062]: using channel 1 Jan 18 20:12:03 Cricket pppd[3062]: Using interface ppp0 Jan 18 20:12:03 Cricket pppd[3062]: Connect: ppp0 <--> /dev/ttyACM0 Jan 18 20:12:04 Cricket pppd[3062]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] Jan 18 20:12:07 Cricket pppd[3062]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <auth chap MD5> <magic 0xf27b8c09> <pcomp> <accomp>] Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP ConfNak id=0x1 <auth pap>] Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfReq id=0x2 <asyncmap 0x0> <auth pap> <magic 0xf27b8c09> <pcomp> <accomp>] Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP ConfAck id=0x2 <asyncmap 0x0> <auth pap> <magic 0xf27b8c09> <pcomp> <accomp>] Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP EchoReq id=0x0 magic=0xeaf2ceb9] Jan 18 20:12:09 Cricket pppd[3062]: sent [PAP AuthReq id=0x1 user="Cricket" password=<hidden>] Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP EchoRep id=0x0 magic=0xf27b8c09] Jan 18 20:12:10 Cricket pppd[3062]: rcvd [PAP AuthAck id=0x1 ""] Jan 18 20:12:10 Cricket pppd[3062]: PAP authentication succeeded Jan 18 20:12:10 Cricket pppd[3062]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Jan 18 20:12:10 Cricket pppd[3062]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>] Jan 18 20:12:10 Cricket pppd[3062]: rcvd [IPCP ConfReq id=0x1 <addr 172.29.122.162>] Jan 18 20:12:10 Cricket pppd[3062]: sent [IPCP ConfAck id=0x1 <addr 172.29.122.162>] Jan 18 20:12:10 Cricket pppd[3062]: rcvd [LCP ProtRej id=0x1 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f] Jan 18 20:12:10 Cricket pppd[3062]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfRej id=0x1 <compress VJ 0f 01>] Jan 18 20:12:11 Cricket pppd[3062]: sent [IPCP ConfReq id=0x2 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>] Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfNak id=0x2 <addr 10.100.73.203> <ms-dns1 172.28.221.53> <ms-dns3 172.28.221.54>] Jan 18 20:12:11 Cricket pppd[3062]: sent [IPCP ConfReq id=0x3 <addr 10.100.73.203> <ms-dns1 172.28.221.53> <ms-dns3 172.28.221.54>] Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfAck id=0x3 <addr 10.100.73.203> <ms-dns1 172.28.221.53> <ms-dns3 172.28.221.54>] Jan 18 20:12:11 Cricket pppd[3062]: local IP address 10.100.73.203 Jan 18 20:12:11 Cricket pppd[3062]: remote IP address 172.29.122.162 Jan 18 20:12:11 Cricket pppd[3062]: primary DNS address 172.28.221.53 Jan 18 20:12:11 Cricket pppd[3062]: secondary DNS address 172.28.221.54 Jan 18 20:12:11 Cricket pppd[3062]: Script /etc/ppp/ip-up started (pid 3912) Jan 18 20:12:12 Cricket pppd[3062]: Script /etc/ppp/ip-up finished (pid 3912), status = 0x0 Here is the messages log from the time of the restart (showing the script failure): Jan 18 20:11:25 Cricket chat[3106]: abort on (NO CARRIER) Jan 18 20:11:25 Cricket chat[3106]: abort on (NO DIALTONE) Jan 18 20:11:25 Cricket chat[3106]: abort on (ERROR) Jan 18 20:11:25 Cricket chat[3106]: abort on (NO ANSWER) Jan 18 20:11:25 Cricket chat[3106]: abort on (BUSY) Jan 18 20:11:25 Cricket chat[3106]: send (AT^M) Jan 18 20:11:25 Cricket chat[3106]: expect (OK) Jan 18 20:11:25 Cricket chat[3106]: AT^M^M Jan 18 20:11:25 Cricket chat[3106]: OK Jan 18 20:11:25 Cricket chat[3106]: -- got it Jan 18 20:11:25 Cricket chat[3106]: send (ATDT#777^M) Jan 18 20:11:25 Cricket chat[3106]: expect (CONNECT) Jan 18 20:11:25 Cricket chat[3106]: ^M Jan 18 20:11:25 Cricket chat[3106]: ATDT#777^M^M Jan 18 20:11:25 Cricket chat[3106]: NO CARRIER Jan 18 20:11:25 Cricket chat[3106]: -- failed Jan 18 20:11:25 Cricket chat[3106]: Failed (NO CARRIER) Jan 18 20:11:57 Cricket chat[3652]: abort on (NO CARRIER) Jan 18 20:11:57 Cricket chat[3652]: abort on (NO DIALTONE) Jan 18 20:11:57 Cricket chat[3652]: abort on (ERROR) Jan 18 20:11:57 Cricket chat[3652]: abort on (NO ANSWER) Jan 18 20:11:57 Cricket chat[3652]: abort on (BUSY) Jan 18 20:11:57 Cricket chat[3652]: send (AT^M) Jan 18 20:11:57 Cricket chat[3652]: expect (OK) Jan 18 20:11:57 Cricket chat[3652]: AT^M^M Jan 18 20:11:57 Cricket chat[3652]: OK Jan 18 20:11:57 Cricket chat[3652]: -- got it Jan 18 20:11:57 Cricket chat[3652]: send (ATDT#777^M) Jan 18 20:11:57 Cricket chat[3652]: expect (CONNECT) Jan 18 20:11:57 Cricket chat[3652]: ^M Jan 18 20:12:03 Cricket chat[3652]: ATDT#777^M^M Jan 18 20:12:03 Cricket chat[3652]: CONNECT Jan 18 20:12:03 Cricket chat[3652]: -- got it Jan 18 20:12:03 Cricket pppd[3062]: Serial connection established. Jan 18 20:12:03 Cricket pppd[3062]: Using interface ppp0 Jan 18 20:12:03 Cricket pppd[3062]: Connect: ppp0 <--> /dev/ttyACM0 Jan 18 20:12:10 Cricket pppd[3062]: PAP authentication succeeded > Ah, OK, so somehow the modem is resetting itself off the bus. > Again, I really really would advise getting a new, different modem. There is only one other model. I'll speak with Cricket about the possibility of a swap - out, but I'm not hopeful. They have been far less than accomodating. >>> Can you >>> remove it for your tests? >> >> No. It's built-in to the modem. It's also required for the >> mode-switch. > > OK, so that fact that it is appearing here indicates that the modem > has reset itself. Yes. It is back to the power-on state, except that now it may not become functional. In some cases, an attempt to switch the modem mode fails. In others, the modem can be switched, but udev doesn't recognize it. In yet others, udev recognizes the modem and creates the /dev/ACM0 device, but the modem doesn't respond. Finally, sometimes the modem responds and dials out, but the authentication fails. > Is it possible that for some reason the power to the modem is being > interrupted causing the disconnect-- eg flakey usb port? Of course it is possible. I installed a USB PCI card yesterday. Time will tell if it eliminates some or all of the hardware failures. Using the persistent option in pppd seems like it may have alleviated one common failure mode: the failed authentication after disconnect. The next 24 hours should hopefully prove that one way or the other. I also found one bug in my scripts that was making remote management more difficult. I've put the hardware reset binary project on hold until the results are in from replacing the USB port. I suspect I will need it eventually in any case, but for now I'm letting the system run to see what failures are encountered with the new scripts and the new hardware.
From: unruh on 19 Jan 2010 12:40 On 2010-01-19, lrhorer <lrhorer(a)satx.rr.com> wrote: > >>>> You actually do not have debugging switched on for your pppd (option >>>> debug to pppd) >>> >>> Yes, I do. The debug directive is in the options file. >> >> Good. But what you display is NOT the pppd debug logs. > > Then pppd isn't creating them, unless it is someplace other > than /var/log/. The debug option is in the options file, as I > mentioned. > >> Did you put the line >> daemon.*;local2.* /var/log/daemonlog > > I already responded to that. I did not have to. It was already there. Then you have a non-standard version of pppd. With the debug option, pppd writes detailed reports to the daemon syslog facility. > >> (or whereever you want to put it) into /etc/syslog.conf, and restart >> syslog.conf >> killall -1 syslogd > > Again, as I already mentioned, this isn't necessary. The router has > been both cold and warm booted many, many times, and the logging > parameters were already there when the system was created. > > Oh, and just BTW, this distro does not use syslog.d. It's using > rsyslog.d. not that ity really matters. I do not know rsyslogd. Are you sure it uses /etc/syslog.conf as its configuration file? > >> Have you looked into /var/log/deamonlog ( or whereever you want to put >> it) during that disconnect. > > /var/log/messages and /var/log/syslog are as shown above for the Jan 16 > event. /var/log/daemon.log has been completely empty since Jan 15 > 20:44. There are no logs at all in daemon.log for ppp at any time > going all the way back to Dec 27, although there are logs from ntpd > concerning its listening and shutting down on ppp0. When the Jan 16 > event took place, I was in the middle of writing the chat script for > pppd and setting up pppd as the primary shell. I didn't make any > changes to the options file, but after I started running pppd as the > primary shell (not that it should make a difference), it started doing > more verbose logging. > > There was a lock-up just an hour ago, although this time without a USB > bus reset. I've enabled he persist option in pppd, at least for the > time being. It does allow the system to recover from an ordinary idle > time-out. This event did not involve a USB reset, /dev/ACM0 stayed > online, and the modem was able to respond to AT commands. It would not > dial, however, either using pppd or minicom. The first response to a > simgle AT command was "ERROR" after I shut down pppd and ran minicom to > do some manual testing. > > Here is the log from the event: > > Jan 18 18:29:54 Cricket pppd[5836]: No response to 4 echo-requests > Jan 18 18:29:54 Cricket pppd[5836]: Serial link appears to be > disconnected. OK, pppd is using echos to test if the link is up. It is failing. Ie, the connection has gone down before pppd goes down. This looks more and more like a hardware flaw, either a bug or a bad design. There is NOTHING that software can do to fix it. Only > Jan 18 18:29:54 Cricket pppd[5836]: Connect time 306.6 minutes. > Jan 18 18:29:54 Cricket pppd[5836]: Sent 445560 bytes, received 588608 > bytes. > Jan 18 18:29:54 Cricket pppd[5836]: Script /etc/ppp/ip-down started (pid > 10015) > Jan 18 18:29:54 Cricket pppd[5836]: sent [LCP TermReq id=0x2 "Peer not > responding"] > Jan 18 18:29:54 Cricket pppd[5836]: Script /etc/ppp/ip-down finished > (pid 10015), status = 0x0 pppd has shut itself down. > Jan 18 19:07:17 Cricket pppd[30605]: pppd 2.4.4 started by root, uid 0 > > Again, it produced a lockfile and grabbed /dev/ttyACM0, but it did nit > run the chat script or anything else. I killed pppd again, and ran > minicom to see if the modem was responding on /dev/ttyACM0. It was. I > pulled the modem and reseated it, running pppd, again: ???? > OK, now we are seeing valid pppd debug output. Where did you get this from? > Jan 18 20:12:03 Cricket pppd[3062]: Connect: ppp0 <--> /dev/ttyACM0 > Jan 18 20:12:04 Cricket pppd[3062]: sent [LCP ConfReq id=0x1 <asyncmap > 0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] > Jan 18 20:12:07 Cricket pppd[3062]: sent [LCP ConfReq id=0x1 <asyncmap > 0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] > Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfReq id=0x1 <asyncmap > 0x0> <auth chap MD5> <magic 0xf27b8c09> <pcomp> <accomp>] > Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP ConfNak id=0x1 <auth pap>] > Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfAck id=0x1 <asyncmap > 0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] > Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfReq id=0x2 <asyncmap > 0x0> <auth pap> <magic 0xf27b8c09> <pcomp> <accomp>] > Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP ConfAck id=0x2 <asyncmap > 0x0> <auth pap> <magic 0xf27b8c09> <pcomp> <accomp>] > Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP EchoReq id=0x0 > magic=0xeaf2ceb9] > Jan 18 20:12:09 Cricket pppd[3062]: sent [PAP AuthReq id=0x1 > user="Cricket" password=<hidden>] > Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP EchoRep id=0x0 > magic=0xf27b8c09] > Jan 18 20:12:10 Cricket pppd[3062]: rcvd [PAP AuthAck id=0x1 ""] > Jan 18 20:12:10 Cricket pppd[3062]: PAP authentication succeeded > Jan 18 20:12:10 Cricket pppd[3062]: sent [CCP ConfReq id=0x1 <deflate > 15> <deflate(old#) 15> <bsd v1 15>] > Jan 18 20:12:10 Cricket pppd[3062]: sent [IPCP ConfReq id=0x1 <compress > VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>] > Jan 18 20:12:10 Cricket pppd[3062]: rcvd [IPCP ConfReq id=0x1 <addr > 172.29.122.162>] > Jan 18 20:12:10 Cricket pppd[3062]: sent [IPCP ConfAck id=0x1 <addr > 172.29.122.162>] > Jan 18 20:12:10 Cricket pppd[3062]: rcvd [LCP ProtRej id=0x1 80 fd 01 01 > 00 0f 1a 04 78 00 18 04 78 00 15 03 2f] > Jan 18 20:12:10 Cricket pppd[3062]: Protocol-Reject for 'Compression > Control Protocol' (0x80fd) received PUt in a noccp option. > Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfRej id=0x1 <compress > VJ 0f 01>] And novj > Jan 18 20:12:11 Cricket pppd[3062]: sent [IPCP ConfReq id=0x2 <addr > 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>] > Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfNak id=0x2 <addr > 10.100.73.203> <ms-dns1 172.28.221.53> <ms-dns3 172.28.221.54>] > Jan 18 20:12:11 Cricket pppd[3062]: sent [IPCP ConfReq id=0x3 <addr > 10.100.73.203> <ms-dns1 172.28.221.53> <ms-dns3 172.28.221.54>] > Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfAck id=0x3 <addr > 10.100.73.203> <ms-dns1 172.28.221.53> <ms-dns3 172.28.221.54>] > Jan 18 20:12:11 Cricket pppd[3062]: local IP address 10.100.73.203 > Jan 18 20:12:11 Cricket pppd[3062]: remote IP address 172.29.122.162 > Jan 18 20:12:11 Cricket pppd[3062]: primary DNS address 172.28.221.53 > Jan 18 20:12:11 Cricket pppd[3062]: secondary DNS address 172.28.221.54 > Jan 18 20:12:11 Cricket pppd[3062]: Script /etc/ppp/ip-up started (pid > 3912) > Jan 18 20:12:12 Cricket pppd[3062]: Script /etc/ppp/ip-up finished (pid > 3912), status = 0x0 And you are connected. > > Here is the messages log from the time of the restart (showing the > script failure): > > Jan 18 20:11:25 Cricket chat[3106]: abort on (NO CARRIER) > Jan 18 20:11:25 Cricket chat[3106]: abort on (NO DIALTONE) > Jan 18 20:11:25 Cricket chat[3106]: abort on (ERROR) > Jan 18 20:11:25 Cricket chat[3106]: abort on (NO ANSWER) > Jan 18 20:11:25 Cricket chat[3106]: abort on (BUSY) > Jan 18 20:11:25 Cricket chat[3106]: send (AT^M) > Jan 18 20:11:25 Cricket chat[3106]: expect (OK) > Jan 18 20:11:25 Cricket chat[3106]: AT^M^M > Jan 18 20:11:25 Cricket chat[3106]: OK > Jan 18 20:11:25 Cricket chat[3106]: -- got it > Jan 18 20:11:25 Cricket chat[3106]: send (ATDT#777^M) > Jan 18 20:11:25 Cricket chat[3106]: expect (CONNECT) > Jan 18 20:11:25 Cricket chat[3106]: ^M > Jan 18 20:11:25 Cricket chat[3106]: ATDT#777^M^M > Jan 18 20:11:25 Cricket chat[3106]: NO CARRIER > Jan 18 20:11:25 Cricket chat[3106]: -- failed > Jan 18 20:11:25 Cricket chat[3106]: Failed (NO CARRIER) > Jan 18 20:11:57 Cricket chat[3652]: abort on (NO CARRIER) > Jan 18 20:11:57 Cricket chat[3652]: abort on (NO DIALTONE) > Jan 18 20:11:57 Cricket chat[3652]: abort on (ERROR) > Jan 18 20:11:57 Cricket chat[3652]: abort on (NO ANSWER) > Jan 18 20:11:57 Cricket chat[3652]: abort on (BUSY) > Jan 18 20:11:57 Cricket chat[3652]: send (AT^M) > Jan 18 20:11:57 Cricket chat[3652]: expect (OK) > Jan 18 20:11:57 Cricket chat[3652]: AT^M^M > Jan 18 20:11:57 Cricket chat[3652]: OK > Jan 18 20:11:57 Cricket chat[3652]: -- got it > Jan 18 20:11:57 Cricket chat[3652]: send (ATDT#777^M) > Jan 18 20:11:57 Cricket chat[3652]: expect (CONNECT) > Jan 18 20:11:57 Cricket chat[3652]: ^M > Jan 18 20:12:03 Cricket chat[3652]: ATDT#777^M^M > Jan 18 20:12:03 Cricket chat[3652]: CONNECT > Jan 18 20:12:03 Cricket chat[3652]: -- got it > Jan 18 20:12:03 Cricket pppd[3062]: Serial connection established. > Jan 18 20:12:03 Cricket pppd[3062]: Using interface ppp0 > Jan 18 20:12:03 Cricket pppd[3062]: Connect: ppp0 <--> /dev/ttyACM0 > Jan 18 20:12:10 Cricket pppd[3062]: PAP authentication succeeded > >> Ah, OK, so somehow the modem is resetting itself off the bus. >> Again, I really really would advise getting a new, different modem. > > There is only one other model. I'll speak with Cricket about the > possibility of a swap - out, but I'm not hopeful. They have been far > less than accomodating. The question is whether or not there are versions which Cricket does not supply. > >>>> Can you >>>> remove it for your tests? >>> >>> No. It's built-in to the modem. It's also required for the >>> mode-switch. >> >> OK, so that fact that it is appearing here indicates that the modem >> has reset itself. > > Yes. It is back to the power-on state, except that now it may not > become functional. In some cases, an attempt to switch the modem mode > fails. In others, the modem can be switched, but udev doesn't > recognize it. In yet others, udev recognizes the modem and creates > the /dev/ACM0 device, but the modem doesn't respond. Finally, > sometimes the modem responds and dials out, but the authentication > fails. Again hardware. > >> Is it possible that for some reason the power to the modem is being >> interrupted causing the disconnect-- eg flakey usb port? > > Of course it is possible. I installed a USB PCI card yesterday. Time > will tell if it eliminates some or all of the hardware failures. Using > the persistent option in pppd seems like it may have alleviated one > common failure mode: the failed authentication after disconnect. The > next 24 hours should hopefully prove that one way or the other. I also > found one bug in my scripts that was making remote management more > difficult. I've put the hardware reset binary project on hold until > the results are in from replacing the USB port. I suspect I will need > it eventually in any case, but for now I'm letting the system run to > see what failures are encountered with the new scripts and the new > hardware.
From: Moe Trin on 19 Jan 2010 14:38 On Mon, 18 Jan 2010, in the Usenet newsgroup comp.os.linux.networking, in article <JOydnYNd4P63u8jWnZ2dnUVZ_vRi4p2d(a)giganews.com>, lrhorer wrote: >There was a lock-up just an hour ago, although this time without a USB >bus reset. I've enabled he persist option in pppd, at least for the >time being. It does allow the system to recover from an ordinary idle >time-out. This event did not involve a USB reset, /dev/ACM0 stayed >online, and the modem was able to respond to AT commands. It would not >dial, however, either using pppd or minicom. Minor confusion - your log shows pppd unable to communicate with the modem between (at least) 18:29:54 and 20:11:24. >Jan 18 18:29:54 Cricket pppd[5836]: No response to 4 echo-requests >Jan 18 18:29:54 Cricket pppd[5836]: Serial link appears to be >disconnected. >Jan 18 18:29:54 Cricket pppd[5836]: Connect time 306.6 minutes. >Jan 18 18:29:54 Cricket pppd[5836]: Sent 445560 bytes, received 588608 >bytes. >Jan 18 18:29:54 Cricket pppd[5836]: Script /etc/ppp/ip-down started (pid >10015) >Jan 18 18:29:54 Cricket pppd[5836]: sent [LCP TermReq id=0x2 "Peer not >responding"] >Jan 18 18:29:54 Cricket pppd[5836]: Script /etc/ppp/ip-down finished >(pid 10015), status = 0x0 >Jan 18 18:29:57 Cricket pppd[5836]: sent [LCP TermReq id=0x3 "Peer not >responding"] >Jan 18 18:30:00 Cricket pppd[5836]: Connection terminated. LCP Echo is used to detect link failure where the link goes down, but the modem (which means the central office) doesn't recognize this and remains off-hook. pppd is here shown sending two TermReq, but the peer isn't responding. The link may have existed at the physical level, but was unable to pass packets. >Jan 18 18:31:57 Cricket pppd[5836]: Hangup (SIGHUP) >Jan 18 18:31:57 Cricket pppd[5836]: Modem hangup Nearly two minutes - why? pppd hangs up the modem using the DTR "wire" which is emulated in a USB modem. "Module problems"? >Jan 18 18:31:58 Cricket pppd[5836]: Hangup (SIGHUP) >Jan 18 18:32:04 Cricket chat[10941]: Can't get terminal parameters: >Input/output error On an attempted restart, the serial port wasn't a serial port. >That's it. Pppd did not shut down, did not release the loackfile, and >did not release /dev/ttyACM0. I shut down pppd with `kill -9`, and >re-started it. Try to avoid using -SIGKILL (-9). The results are messy. -SIGTERM (-15) should be enough. >After restart, it produced only a single line in syslog: > >Jan 18 19:07:17 Cricket pppd[30605]: pppd 2.4.4 started by root, uid 0 > > Again, it produced a lockfile and grabbed /dev/ttyACM0, but it >did nit run the chat script or anything else. I'm assuming you used 'fuser' or 'lsof' to determine that pppd had the device. Assuming your file system does update access time (some people are mounting -noatime), did 'ls -lu /usr/sbin/chat' show current access? What about the script that contains the dialing commands? >Jan 18 20:11:24 Cricket pppd[3062]: pppd 2.4.4 started by root, uid 0 >Jan 18 20:11:25 Cricket pppd[3062]: Connect script failed >Jan 18 20:12:03 Cricket pppd[3062]: Serial connection established. Below >Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfReq id=0x1 <asyncmap >0x0> <auth chap MD5> <magic 0xf27b8c09> <pcomp> <accomp>] >Jan 18 20:12:09 Cricket pppd[3062]: sent [LCP ConfNak id=0x1 <auth pap>] >Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfAck id=0x1 <asyncmap >0x0> <magic 0xeaf2ceb9> <pcomp> <accomp>] >Jan 18 20:12:09 Cricket pppd[3062]: rcvd [LCP ConfReq id=0x2 <asyncmap >0x0> <auth pap> <magic 0xf27b8c09> <pcomp> <accomp>] The peer requested you authenticate by CHAP-MD5 (RFC1994), and you refused, suggesting PAP (RFC1334) instead. This time, the peer accepted it. On 'Jan 9 09:49:00', you showed CHAP authentication working - what changed? I'd suggest having identical pap-secrets and chap-secrets files, and letting pppd use which-ever it needed. >Jan 18 20:12:10 Cricket pppd[3062]: sent [CCP ConfReq id=0x1 <deflate >15> <deflate(old#) 15> <bsd v1 15>] >Jan 18 20:12:10 Cricket pppd[3062]: sent [IPCP ConfReq id=0x1 <compress >VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns3 0.0.0.0>] >Jan 18 20:12:10 Cricket pppd[3062]: rcvd [LCP ProtRej id=0x1 80 fd 01 01 >00 0f 1a 04 78 00 18 04 78 00 15 03 2f] >Jan 18 20:12:10 Cricket pppd[3062]: Protocol-Reject for 'Compression >Control Protocol' (0x80fd) received >Jan 18 20:12:11 Cricket pppd[3062]: rcvd [IPCP ConfRej id=0x1 <compress >VJ 0f 01>] This peer doesn't do CCP (RFC1962), or Van Jacobson header compression (RFC1144). No big deal, but you _could_ add 'noccp' and 'novj' if it did become a problem. It's _not_ a problem now. >Jan 18 20:11:25 Cricket chat[3106]: abort on (BUSY) >Jan 18 20:11:25 Cricket chat[3106]: send (AT^M) >Jan 18 20:11:25 Cricket chat[3106]: expect (OK) >Jan 18 20:11:25 Cricket chat[3106]: AT^M^M >Jan 18 20:11:25 Cricket chat[3106]: OK An empty 'Hayes' command prefix - not very reliable at initializing the modem. >Jan 18 20:11:25 Cricket chat[3106]: send (ATDT#777^M) >Jan 18 20:11:25 Cricket chat[3106]: expect (CONNECT) >Jan 18 20:11:25 Cricket chat[3106]: ^M >Jan 18 20:11:25 Cricket chat[3106]: ATDT#777^M^M >Jan 18 20:11:25 Cricket chat[3106]: NO CARRIER >Jan 18 20:11:25 Cricket chat[3106]: -- failed You told the modem to dial - it responded with 'NO CARRIER' rather than the expected 'CONNECT blah, blah, blah'. That's a modem issue. >Jan 18 20:11:57 Cricket chat[3652]: send (ATDT#777^M) >Jan 18 20:11:57 Cricket chat[3652]: expect (CONNECT) >Jan 18 20:11:57 Cricket chat[3652]: ^M >Jan 18 20:12:03 Cricket chat[3652]: ATDT#777^M^M >Jan 18 20:12:03 Cricket chat[3652]: CONNECT >Jan 18 20:12:03 Cricket chat[3652]: -- got it You tried again, and the modem took six seconds, but this time reported it found another modem to talk to. >Finally, sometimes the modem responds and dials out, but the >authentication fails. Above - '/bin/cp /etc/ppp/pap-secrets /etc/ppp/chap-secrets' Old guy
From: Jerry Peters on 19 Jan 2010 16:30
lrhorer <lrhorer(a)satx.rr.com> wrote: >>>> No I'm not sure, hence the "I believe" part. It could also require >>>> an ioctl or some other special operation. What happens if you remove >>>> [eou]hci-hcd (the USB port driver)? >>> >>> Nothing at all, I think. I believe the device has to be >>> commanded to >>> down the port (and I believe it is port specific). I also have to >>> qualify the statement with "I believe", because that just what the >>> reading I have done and the people to whom I have spoken so far has >>> suggested. One of the USB gurus tho whom I have spoken (Alan Stern >>> at Harvard) has suggested the best way to approach the issue is to >>> unbind the driver and then issue the command to shut down power on >>> the port. That makes me think unbinding the driver isn't sufficient >>> by itself. >> >> linux/Documentation/usb/power-management.txt > > My system does not have that file. I found a copy on the web. > >> Though I don't see any files except wakeup in the power >> sub-directories when I look. Could be my Aspire 1 ports don't support >> power management, or I didn't have the necessary options set when I >> built the kernel. Found the necessary files: ~$ ls /sys/bus/usb/devices/usb?/power /sys/bus/usb/devices/usb1/power: active_duration autosuspend connected_duration level wakeup /sys/bus/usb/devices/usb2/power: active_duration autosuspend connected_duration level wakeup /sys/bus/usb/devices/usb3/power: active_duration autosuspend connected_duration level wakeup /sys/bus/usb/devices/usb4/power: active_duration autosuspend connected_duration level wakeup /sys/bus/usb/devices/usb5/power: active_duration autosuspend connected_duration level wakeup And here's what the files look like for usb1: ~$ grep '.' /sys/bus/usb/devices/usb1/power/* /sys/bus/usb/devices/usb1/power/active_duration:9144 /sys/bus/usb/devices/usb1/power/autosuspend:2 /sys/bus/usb/devices/usb1/power/connected_duration:1128124 /sys/bus/usb/devices/usb1/power/level:auto /sys/bus/usb/devices/usb1/power/wakeup:enabled The usb[1-5] devices must represent the USB ports themselves, since AFAIK there are 5 USB ports on this AA1, 3 external and 2 internal. So power control via sysfs at least appears feasible. Jerry |