Date: Mon, 11 Feb 2013 02:06:35 +1100 (EST) From: Ian Smith <smithi@nimnet.asn.au> To: Kevin Oberman <kob6558@gmail.com> Cc: Adrian Chadd <adrian@freebsd.org>, freebsd-mobile@freebsd.org Subject: Re: Notes; Lenovo T400 Message-ID: <20130211001022.R71572@sola.nimnet.asn.au> In-Reply-To: <CAN6yY1uiH0WQS_3p4zvnFn1epKy=3wuf7c7Pi3_UwL-d_BTGyg@mail.gmail.com> References: <CAJ-Vmo=GXtRuaOp5rmWN6FYQUtYNj5tpgiKHaoKZnwfBnjpAnQ@mail.gmail.com> <CAN6yY1u_WtsYJB%2BP05MtyQ4Gzkc=UyrWJCn0huOdY31CcbawVg@mail.gmail.com> <CAJ-VmonoVQpyULwWmkyfLbJ6d88XgbyESocq=nNLMh7qnYD05Q@mail.gmail.com> <CAN6yY1sL5SgHimJAwwkycmfBF-%2BLzOYC3XyYuqjfQUaT1=caJg@mail.gmail.com> <20130204020335.U87033@sola.nimnet.asn.au> <CAN6yY1uiH0WQS_3p4zvnFn1epKy=3wuf7c7Pi3_UwL-d_BTGyg@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On Fri, 8 Feb 2013 22:52:13 -0800, Kevin Oberman wrote: > On Sun, Feb 3, 2013 at 7:10 AM, Ian Smith <smithi@nimnet.asn.au> wrote: > > On Sat, 2 Feb 2013 22:46:26 -0800, Kevin Oberman wrote: > > > On Fri, Feb 1, 2013 at 5:36 PM, Adrian Chadd <adrian@freebsd.org> wrote: > > > > Yeah I commented it out to make it work. > > > > > > > > Try booting to single user mode and then try a suspend/resume pass. > > > > > > > > > > > > > > > > Adrian > > > > > > > > > > > > On 1 February 2013 17:34, Kevin Oberman <kob6558@gmail.com> wrote: > > > >> Adrian, > > > >> > > > >> Can I assume that you did NOT have the '#' in the sysctl.conf? (Still > > > >> hoping to et my T520 to resume some day.) > > > >> > > > >> On Wed, Jan 30, 2013 at 9:35 PM, Adrian Chadd <adrian@freebsd.org> wrote: > > > >>> Hi, > > > >>> > > > >>> It turns out my Lenovo T400 issue? It was because in /etc/sysctl.conf > > > >>> I had this: > > > >>> > > > >>> # hw.acpi.reset_video=1 > > > >>> > > > >>> .. don't do that. > > > >>> > > > >>> > > > >>> > > > >>> Adrian > > > > > > Almost worked. I saw several acpi power state errors as the system > > > suspended. On resume, the system came back up, but the display > > > remained off (no backlight). I was able to type 'shutdown -r now' and > > > do a clean reboot. Of course, the number of differences between single > > > and multi-user are substantial, but this eliminates a LOT of things. > > > > > > I then tried coming up to multi-user, but not starting X (Gnome). > > > Again, it suspended and resumed with no display. My network came up > > > and I sshed into the system from my phone. Then I got an interrupt > > > from my greyhounds. Time to brush their teeth. I was away from the > > > laptop for about 10 minutes. When I came back, it was dead. My ssh > > > session was hung and I could no longer ping it. :-( > > > > > > Weird. It's getting really close, but not quite. I suspect that the > > > video ties into it in some way. I also mount a couple of FUSE NTFS > > > partitions when I start X (Gnome auto-mounts them). When I suspend in > > > Gnome, the network never comes back up and the power LED pulses just > > > like it does while suspended, so it really does not finish the resume. Sounds more like it doesn't or scarcely begins the resume in the latter case; powering up from S3 sleep sufficiently to run resume code is pretty low level BIOS stuff I'd have thought, power LED and such? I clearly know nothing about video issues these days, but 'blank screen on resume' seems to come up pretty often. Maybe more on acpi@? > > > I think I can now eliminate the wireless (iwn), at least. > > > > > > Thanks for the suggestions! > > > > Kevin, have you tried doing suspend/resume after booting with verbose > > messages? If you can get in eg ssh as above, you can dmesg > file and > > even if you can't, it should all be there in /var/log/messages .. I've > > found it handy to see all the blow-by-blow disabling of devices then > > reenabling after resume for working out what happened (or didn't :) > > > > You can also increase ACPI verbosity, but I've rarely needed to. > > Finally gave it a try, but nothing looks very odd to me. It stays > responsive for about a couple of minutes and then stops responding to > either the ssh session or the keyboard. > > Here are the contents of messages for the suspend and the resume. I > don't really see anything very bad. Looks like firewire has a problem. Just a few likely unhelpful observations .. First thing I noticed was the lack of my very old friend, the 'wakeup from sleeping state (slept hh:mm:ss)' line, which marks wakeup, busses ablaze, before device reconfig. Is this on -current? > Feb 8 22:26:17 rogue console-kit-daemon[1509]: WARNING: kvm_getenvv failed: > Feb 8 22:26:17 rogue kernel: blanktime screensaver > Feb 8 22:26:17 rogue kernel: splash: image decoder found: logo_saver I guess you've tried disabling screensavers? Recalling older issues .. > Feb 8 22:26:21 rogue ntpd[1351]: time reset -1.063975 s > Feb 8 22:26:24 rogue login: ROOT LOGIN (root) ON ttyv0 > Feb 8 22:26:45 rogue acpi: suspend at 20130208 22:26:45 > Feb 8 22:26:48 rogue kernel: acpi_timer0: switching timecounter, > TSC-low -> ACPI-fast Switching timecounters is news; I must read more commit messages! :) > Feb 8 22:26:48 rogue kernel: (ada0:ahcich0:0:0:0): spin-down > Feb 8 22:26:49 rogue kernel: (ada1:ahcich1:0:0:0): spin-down > Feb 8 22:27:03 rogue kernel: acpi_lid0: wake_prep enabled for \_SB_.LID_ (S3) > Feb 8 22:27:03 rogue kernel: acpi_button0: wake_prep enabled for > \_SB_.SLPB (S3) > Feb 8 22:27:03 rogue kernel: uhub0: at usbus0, port 1, addr 1 (disconnected) > Feb 8 22:27:03 rogue kernel: ugen0.2: <vendor 0x8087> at usbus0 (disconnected) > Feb 8 22:27:03 rogue kernel: uhub2: at uhub0, port 1, addr 2 (disconnected) > Feb 8 22:27:03 rogue kernel: ugen0.3: <Chicony Electronics Co., Ltd.> > at usbus0 (disconnected) > Feb 8 22:27:03 rogue kernel: pci0:0:28:0: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: wlan0: link state changed to DOWN > Feb 8 22:27:03 rogue kernel: pci0:3:0:0: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: pci0:0:28:1: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: pci0:0:28:3: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: fwohci0: fwohci_pci_suspend > Feb 8 22:27:03 rogue kernel: pci0:13:0:0: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: pci0:13:0:3: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: pci0:0:28:4: Transition from D0 to D3 > Feb 8 22:27:03 rogue kernel: uhub1: at usbus1, port 1, addr 1 (disconnected) > Feb 8 22:27:03 rogue kernel: ugen1.2: <vendor 0x8087> at usbus1 (disconnected) > Feb 8 22:27:03 rogue kernel: uhub3: at uhub1, port 1, addr 2 (disconnected) No surprises, without knowing your device mapping .. > Feb 8 22:27:03 rogue kernel: vga0: saving 6724 bytes of video state > Feb 8 22:27:03 rogue kernel: vga0: saving color palette Less than twice the size of state saved by my lil' S3 Savage card :) > Feb 8 22:27:03 rogue kernel: pci0: failed to set ACPI power state D2 > on \_SB_.PCI0.EXP1: AE_BAD_PARAMETER > Feb 8 22:27:03 rogue kernel: pci0: failed to set ACPI power state D2 > on \_SB_.PCI0.EXP2: AE_BAD_PARAMETER > Feb 8 22:27:03 rogue kernel: pci0: failed to set ACPI power state D2 > on \_SB_.PCI0.EXP4: AE_BAD_PARAMETER > Feb 8 22:27:03 rogue kernel: pci0: failed to set ACPI power state D2 > on \_SB_.PCI0.EXP5: AE_BAD_PARAMETER Card reader I guess? I get the same messages on 9.1 for both cardbus bridges. All below are on the resume path after the wakeup. > Feb 8 22:27:03 rogue kernel: acpi_lid0: run_prep cleaned up for \_SB_.LID_ > Feb 8 22:27:03 rogue kernel: acpi_button0: run_prep cleaned up for \_SB_.SLPB > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.VID_ I wish I knew something about how X resumes graphic video state, or what triggers it to .. I guess it has its own resume method? Is that suspect? > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.IGBE > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EHC2 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.HDEF > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP1 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP2 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP4 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP5 I see the above four repeated below, plus .EXP5.SLOT. I don't get that. > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EHC1 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.LPC_ > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.SAT1 > Feb 8 22:27:03 rogue kernel: pci0:0:22:0: Transition from D0 to D3 Hmm, what is pci0:0:22:0 and why is it going back to sleep? firewire? > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP1 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP2 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP4 > Feb 8 22:27:03 rogue kernel: pci0: set ACPI power state D0 on \_SB_.PCI0.EXP5 > Feb 8 22:27:03 rogue kernel: pci13: set ACPI power state D0 on > \_SB_.PCI0.EXP5.SLOT A card in one of the slots? > Feb 8 22:27:03 rogue kernel: fwohci0: Phy 1394a available S400, 1 ports. > Feb 8 22:27:03 rogue kernel: fwohci0: Link S400, max_rec 2048 bytes. > Feb 8 22:27:03 rogue kernel: fwohci0: Initiate bus reset > Feb 8 22:27:03 rogue kernel: vga0: calling BIOS POST > Feb 8 22:27:03 rogue kernel: fwohci0: fwohci_intr_core: BUS reset > Feb 8 22:27:03 rogue kernel: fwohci0: fwohci_intr_core: > node_id=0x00000000, SelfID Count=1, CYCLEMASTER mode > Feb 8 22:27:03 rogue kernel: firewire0: 1 nodes, maxhop <= 0 cable > IRM irm(0) (me) > Feb 8 22:27:03 rogue kernel: firewire0: bus manager 0 > Feb 8 22:27:03 rogue kernel: fwohci0: unrecoverable error Yes it looks unhappy. BIOS POST amidst that is probably coincidence. > Feb 8 22:27:03 rogue kernel: hdaa0: Headphones redirection for > association 0 nid=25 using unsolicited responses. > Feb 8 22:27:03 rogue kernel: ahcich0: AHCI reset... > Feb 8 22:27:03 rogue kernel: ahcich0: SATA connect time=1000us status=00000123 > Feb 8 22:27:03 rogue kernel: ahcich0: AHCI reset: device found > Feb 8 22:27:03 rogue kernel: ahcich1: AHCI reset... > Feb 8 22:27:03 rogue kernel: ahcich1: SATA connect time=1000us status=00000123 > Feb 8 22:27:03 rogue kernel: ahcich1: AHCI reset: device found > Feb 8 22:27:03 rogue kernel: ahcich3: AHCI reset... > Feb 8 22:27:03 rogue kernel: ahcich3: SATA connect timeout > time=10000us status=00000000 > Feb 8 22:27:03 rogue kernel: ahcich3: AHCI reset: device not found > Feb 8 22:27:03 rogue kernel: ahcich4: AHCI reset... > Feb 8 22:27:03 rogue kernel: ahcich4: SATA connect timeout > time=10000us status=00000000 > Feb 8 22:27:03 rogue kernel: ahcich4: AHCI reset: device not found > Feb 8 22:27:03 rogue kernel: atkbd: the current kbd controller > command byte 0047 > Feb 8 22:27:03 rogue kernel: atkbd: keyboard ID 0x54ab (2) > Feb 8 22:27:03 rogue kernel: kbdc: RESET_KBD return code:00fa > Feb 8 22:27:03 rogue kernel: kbdc: RESET_KBD status:00aa > Feb 8 22:27:03 rogue kernel: kbdc: TEST_AUX_PORT status:0000 > Feb 8 22:27:03 rogue kernel: kbdc: RESET_AUX return code:00fa > Feb 8 22:27:03 rogue kernel: kbdc: RESET_AUX status:00aa > Feb 8 22:27:03 rogue kernel: kbdc: RESET_AUX ID:0000 All that looks 'normal' from here, given AHCI/SATA rather than ATA/PATA. > Feb 8 22:27:03 rogue kernel: firmware: 'iwn6000g2afw' version 0: > 444128 bytes loaded at 0xffffffff8183c0b0 > Feb 8 22:27:03 rogue kernel: battery0: battery initialization start > Feb 8 22:27:03 rogue kernel: uhub0: <Intel EHCI root HUB, class 9/0, > rev 2.00/1.00, addr 1> on usbus1 > Feb 8 22:27:03 rogue kernel: uhub1: <Intel EHCI root HUB, class 9/0, > rev 2.00/1.00, addr 1> on usbus0 > Feb 8 22:27:03 rogue kernel: ahcich0: AHCI reset: device ready after 800ms > Feb 8 22:27:03 rogue kernel: ahcich1: AHCI reset: device ready after 1200ms > Feb 8 22:27:03 rogue kernel: uhub0: 3 ports with 3 removable, self powered > Feb 8 22:27:03 rogue kernel: uhub1: 3 ports with 3 removable, self powered > Feb 8 22:27:03 rogue kernel: ugen1.2: <vendor 0x8087> at usbus1 > Feb 8 22:27:03 rogue kernel: uhub2: <vendor 0x8087 product 0x0024, > class 9/0, rev 2.00/0.00, addr 2> on usbus1 > Feb 8 22:27:03 rogue kernel: ugen0.2: <vendor 0x8087> at usbus0 > Feb 8 22:27:03 rogue kernel: uhub3: <vendor 0x8087 product 0x0024, > class 9/0, rev 2.00/0.00, addr 2> on usbus0 > Feb 8 22:27:03 rogue kernel: uhub3: 6 ports with 6 removable, self powered > Feb 8 22:27:03 rogue kernel: battery0: battery initialization done, > tried 1 times > Feb 8 22:27:03 rogue kernel: wlan0: link state changed to UP > Feb 8 22:27:03 rogue kernel: uhub2: 8 ports with 8 removable, self powered > Feb 8 22:27:03 rogue kernel: (ada0:ahcich0:0:0:0): resume > Feb 8 22:27:03 rogue kernel: (ada1:ahcich1:0:0:0): resume Seems uneventful. > Feb 8 22:27:03 rogue kernel: acpi_timer0: restoring timecounter, > ACPI-fast -> TSC-low I'm curious about this. Note the next log timestamp is at least 13 seconds earlier, but maybe that's why we're using TSC-low instead? Yes, looks like wireless is working below .. The fact that it resumed, sans backlight - is there anything that could poke that from /etc/rc.resume? DPMS? - but then died inside 10 minutes seems a bit spooky. I remember from DOS days - the screensaver dun it! cheers, Ian > Feb 8 22:26:50 rogue wpa_supplicant[538]: CTRL-EVENT-DISCONNECTED > bssid=00:26:b8:67:c3:2d reason=0 > Feb 8 22:26:50 rogue wpa_supplicant[538]: Failed to initiate AP scan. > Feb 8 22:26:53 rogue last message repeated 3 times > Feb 8 22:26:57 rogue wpa_supplicant[538]: Trying to associate with > 00:26:b8:67:c3:2d (SSID='babcom' freq=2437 MHz) > Feb 8 22:26:57 rogue wpa_supplicant[538]: Associated with 00:26:b8:67:c3:2d > Feb 8 22:26:57 rogue wpa_supplicant[538]: WPA: Key negotiation > completed with 00:26:b8:67:c3:2d [PTK=CCMP GTK=CCMP] > Feb 8 22:26:57 rogue wpa_supplicant[538]: CTRL-EVENT-CONNECTED - > Connection to 00:26:b8:67:c3:2d completed (reauth) [id=1 id_str=] > Feb 8 22:27:03 rogue acpi: resumed at 20130208 22:27:03 > Feb 8 22:27:03 rogue dhclient: New IP Address (wlan0): 192.168.1.5 > Feb 8 22:27:03 rogue dhclient: New Subnet Mask (wlan0): 255.255.255.0 > Feb 8 22:27:03 rogue dhclient: New Broadcast Address (wlan0): 192.168.1.255 > Feb 8 22:27:03 rogue dhclient: New Routers (wlan0): 192.168.1.1 > Feb 8 22:27:03 rogue root: Unknown USB device: vendor 0x04f2 product > 0xb217 bus uhub3 > Feb 8 22:27:03 rogue kernel: ugen0.3: <Chicony Electronics Co., Ltd.> at usbus0 > Feb 8 22:27:03 rogue root: Unknown USB device: vendor 0x04f2 product > 0xb217 bus uhub3 > Feb 8 22:27:41 rogue sudo: oberman : TTY=pts/0 ; > PWD=/usr/home/oberman ; USER=root ; COMMAND=/bin/csh > Feb 8 22:27:52 rogue wpa_supplicant[538]: WPA: Group rekeying > completed with 00:26:b8:67:c3:2d [GTK=CCMP] > -- > R. Kevin Oberman, Network Engineer > E-mail: kob6558@gmail.com
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20130211001022.R71572>