Bug 14105

Summary: pcmcia cards stop working after resuming from snapshot cycle (hibernation)
Product: Power Management Reporter: Martin Steigerwald (Martin)
Component: Hibernation/SuspendAssignee: power-management_other
Status: CLOSED DUPLICATE    
Severity: normal CC: akpm, rjw, rui.zhang
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.31-rc7 Subsystem:
Regression: Yes Bisected commit-id:
Bug Depends on:    
Bug Blocks: 7216, 13070    
Attachments: config for kernel that works okay on my ThinkPad T42
config for latest kernel that doesn't work on ThinkPad T42
config for kernel that works okay on my ThinkPad T23
config for first kernel that didn´t work on my ThinkPad T23
config for recent kernel that doesn't work on my ThinkPad T23

Description Martin Steigerwald 2009-09-01 19:44:45 UTC
I am not sure whether this issue should be sorted to PCMCIA or ACPI. Please feel free to reassign.

Kernels that show this problem:

martin@deepdance:~> cat /proc/version
Linux version 2.6.31-rc7-tp23-toi-3.0.1-04741-g57e61c0 (martin@deepdance) (gcc version 4.3.3 (Debian 4.3.3-10) ) #2 PREEMPT Sun Aug 23 12:05:01 CEST 2009

and 2.6.31-rc5-tp23-toi-3.0.1-05139-gb4d43f4 on a ThinkPad T23


martin@shambhala:~> cat /proc/version
Linux version 2.6.31-rc7-tp42-toi-3.0.1-04741-g57e61c0 (martin@shambhala) (gcc version 4.3.3 (Debian 4.3.3-10) ) #6 PREEMPT Sun Aug 23 10:51:32 CEST 2009

and 2.6.31-rc5-tp42-toi-3.0.1-05139-gb4d43f4


Last kernels that work correctly:

- 2.6.29.2-tp23-toi-3.0.1 on my T23
- 2.6.29.6-tp42-toi-3.0.1-01085-gf325e4a on my T42

2.6.31-rc5 and 2.6.31-rc7 are from: http://git.kernel.org/?p=linux/kernel/git/nigelc/tuxonice-head.git;a=summary

2.6.29.6 on my T42 is from: http://git.kernel.org/?p=linux/kernel/git/nigelc/tuxonice-2.6.29.git;a=summary

2.6.29.2 on my T23 is from kernel.org and tuxonice.org - manually patched.

I will attach configs. All are with TuxOnIce. I know TuxOnIce is not in vanilla, but I think the problem has nothing to do with TuxOnIce since TuxOnIce simply uses ACPI S4. I can't easily test without it, cause I didn't get in kernel snapshotting to work, neither without nor with userspace. I got hangs on hibernation or on resume. It used to work once, but it didn't with 2.6.31 and 2.6.30 which I tried last and some previous kernels. 

I can't report against 2.6.30 even with TuxOnice, cause 2.6.30 and 2.6.31 upto rc5 did not work with TuxOnIce either. It reboots or hangs after resume and gives some backtraces on hibernating: http://lists.tuxonice.net/lurker/message/20090617.200943.f5eea8fe.en.html
(I don't think lurker shows the complete thread)


What happens:

On resume the PCMCIA does not work anymore. It seems that the kernel still sees it:

deepdance:~> lspcmcia
Socket 0 Bridge:        [yenta_cardbus]         (bus ID: 0000:02:00.0)
  CardBus card -- see "lspci" for more information
Socket 1 Bridge:        [yenta_cardbus]         (bus ID: 0000:02:00.1)

deepdance:~> lspci -nn | egrep "CardBus|NEC"
02:00.0 CardBus bridge [0607]: Texas Instruments PCI1420 PC card Cardbus Controller [104c:ac51]
02:00.1 CardBus bridge [0607]: Texas Instruments PCI1420 PC card Cardbus Controller [104c:ac51]
03:00.0 USB Controller [0c03]: NEC Corporation USB [1033:0035] (rev 43)
03:00.1 USB Controller [0c03]: NEC Corporation USB [1033:0035] (rev 43)
03:00.2 USB Controller [0c03]: NEC Corporation USB 2.0 [1033:00e0] (rev 04)

This is on my T23. There is a mouse connected to the USB PCMCIA controller that doesn't work after resume. It doesn't help to disconnect and reconnect the mouse. The kernel just doesn't notice this at all according to syslog. The USB soundcard Sonica Theater which is connected to the USB port of the port replicator (kind of minimal docking station for ThinkPads) is recognized and works. I connect it directly to the ThinkPad cause it doesn't work reliably otherwise (audio glitches). Since the port replicator does only have one USB port I connected the mouse to that existing NEC USB PCMCIA card.

Only disconnecting and reconnecting the PCMCIA USB controller card brings back the mouse.

martin@deepdance:~> grep "kernel" /var/log/syslog | grep -v chrony | grep "21:31"
Sep  1 21:31:40 localhost kernel: pcmcia_socket pcmcia_socket0: pccard: card ejected from slot 0
Sep  1 21:31:40 localhost kernel: ohci_hcd 0000:03:00.0: remove, state 0                        
Sep  1 21:31:40 localhost kernel: usb usb5: USB disconnect, address 1                           
Sep  1 21:31:40 localhost kernel: ohci_hcd 0000:03:00.0: USB bus 5 deregistered                 
Sep  1 21:31:40 localhost kernel: ohci_hcd 0000:03:00.0: PCI INT A disabled                     
Sep  1 21:31:40 localhost kernel: ohci_hcd 0000:03:00.1: remove, state 0                        
Sep  1 21:31:40 localhost kernel: usb usb6: USB disconnect, address 1                           
Sep  1 21:31:40 localhost kernel: ohci_hcd 0000:03:00.1: USB bus 6 deregistered                 
Sep  1 21:31:40 localhost kernel: ohci_hcd 0000:03:00.1: PCI INT B disabled                     
Sep  1 21:31:40 localhost kernel: ehci_hcd 0000:03:00.2: remove, state 0                        
Sep  1 21:31:40 localhost kernel: usb usb4: USB disconnect, address 1                           
Sep  1 21:31:40 localhost kernel: ehci_hcd 0000:03:00.2: USB bus 4 deregistered                 
Sep  1 21:31:40 localhost kernel: ehci_hcd 0000:03:00.2: PCI INT C disabled                     
Sep  1 21:31:44 localhost kernel: pcmcia_socket pcmcia_socket0: pccard: CardBus card inserted into slot 0
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.0: reg 10 32bit mmio: [0x000000-0x000fff]               
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.0: supports D1 D2                                       
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.0: PME# supported from D0 D1 D2 D3hot                   
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.0: PME# disabled                                        
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.1: reg 10 32bit mmio: [0x000000-0x000fff]               
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.1: supports D1 D2                                       
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.1: PME# supported from D0 D1 D2 D3hot                   
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.1: PME# disabled                                        
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.2: reg 10 32bit mmio: [0x000000-0x0000ff]               
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.2: supports D1 D2                                       
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.2: PME# supported from D0 D1 D2 D3hot                   
Sep  1 21:31:44 localhost kernel: pci 0000:03:00.2: PME# disabled                                        
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.0: enabling device (0000 -> 0002)                  
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.0: setting latency timer to 64                             
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.0: OHCI Host Controller                                    
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.0: new USB bus registered, assigned bus number 4           
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.0: irq 11, io mem 0xc4000000                               
Sep  1 21:31:44 localhost kernel: usb usb4: New USB device found, idVendor=1d6b, idProduct=0001                  
Sep  1 21:31:44 localhost kernel: usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1             
Sep  1 21:31:44 localhost kernel: usb usb4: Product: OHCI Host Controller
Sep  1 21:31:44 localhost kernel: usb usb4: Manufacturer: Linux 2.6.31-rc7-tp23-toi-3.0.1-04741-g57e61c0 ohci_hcd
Sep  1 21:31:44 localhost kernel: usb usb4: SerialNumber: 0000:03:00.0
Sep  1 21:31:44 localhost kernel: usb usb4: configuration #1 chosen from 1 choice
Sep  1 21:31:44 localhost kernel: hub 4-0:1.0: USB hub found
Sep  1 21:31:44 localhost kernel: hub 4-0:1.0: 3 ports detected
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.1: enabling device (0000 -> 0002)
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.1: PCI INT B -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.1: setting latency timer to 64
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.1: OHCI Host Controller
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.1: new USB bus registered, assigned bus number 5
Sep  1 21:31:44 localhost kernel: ohci_hcd 0000:03:00.1: irq 11, io mem 0xc4001000
Sep  1 21:31:44 localhost kernel: usb usb5: New USB device found, idVendor=1d6b, idProduct=0001
Sep  1 21:31:44 localhost kernel: usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Sep  1 21:31:44 localhost kernel: usb usb5: Product: OHCI Host Controller
Sep  1 21:31:44 localhost kernel: usb usb5: Manufacturer: Linux 2.6.31-rc7-tp23-toi-3.0.1-04741-g57e61c0 ohci_hcd
Sep  1 21:31:44 localhost kernel: usb usb5: SerialNumber: 0000:03:00.1
Sep  1 21:31:44 localhost kernel: usb usb5: configuration #1 chosen from 1 choice
Sep  1 21:31:44 localhost kernel: hub 5-0:1.0: USB hub found
Sep  1 21:31:44 localhost kernel: hub 5-0:1.0: 2 ports detected
Sep  1 21:31:44 localhost kernel: ehci_hcd 0000:03:00.2: enabling device (0000 -> 0002)
Sep  1 21:31:44 localhost kernel: ehci_hcd 0000:03:00.2: PCI INT C -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
Sep  1 21:31:44 localhost kernel: ehci_hcd 0000:03:00.2: EHCI Host Controller
Sep  1 21:31:44 localhost kernel: ehci_hcd 0000:03:00.2: new USB bus registered, assigned bus number 6
Sep  1 21:31:44 localhost kernel: ehci_hcd 0000:03:00.2: irq 11, io mem 0xc4002000
Sep  1 21:31:44 localhost kernel: ehci_hcd 0000:03:00.2: USB 2.0 started, EHCI 1.00
Sep  1 21:31:44 localhost kernel: usb usb6: New USB device found, idVendor=1d6b, idProduct=0002
Sep  1 21:31:44 localhost kernel: usb usb6: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Sep  1 21:31:44 localhost kernel: usb usb6: Product: EHCI Host Controller
Sep  1 21:31:44 localhost kernel: usb usb6: Manufacturer: Linux 2.6.31-rc7-tp23-toi-3.0.1-04741-g57e61c0 ehci_hcd
Sep  1 21:31:44 localhost kernel: usb usb6: SerialNumber: 0000:03:00.2
Sep  1 21:31:44 localhost kernel: usb usb6: configuration #1 chosen from 1 choice
Sep  1 21:31:44 localhost kernel: hub 6-0:1.0: USB hub found
Sep  1 21:31:44 localhost kernel: hub 6-0:1.0: 5 ports detected
Sep  1 21:31:45 localhost kernel: usb 4-1: new low speed USB device using ohci_hcd and address 2
Sep  1 21:31:45 localhost kernel: usb 4-1: New USB device found, idVendor=046d, idProduct=c001
Sep  1 21:31:45 localhost kernel: usb 4-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Sep  1 21:31:45 localhost kernel: usb 4-1: Product: USB Mouse
Sep  1 21:31:45 localhost kernel: usb 4-1: Manufacturer: Logitech
Sep  1 21:31:45 localhost kernel: usb 4-1: configuration #1 chosen from 1 choice
Sep  1 21:31:45 localhost kernel: input: Logitech USB Mouse as /class/input/input11
Sep  1 21:31:45 localhost kernel: generic-usb 0003:046D:C001.0002: input,hidraw0: USB HID v1.10 Mouse [Logitech USB Mouse] on usb-0000:03:00.0-1/input0


Similar goes with T42 and a PCMCIA eSATA controller from Delock with Silicon Image chipset. A syslog on inserting it normally, a lspcmcia and lspci -nn on it for now:

Sep  1 21:33:14 shambhala kernel: pcmcia_socket pcmcia_socket0: pccard: CardBus card inserted into slot 0
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 10 io port: [0x00-0x07]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 14 io port: [0x00-0x03]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 18 io port: [0x00-0x07]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 1c io port: [0x00-0x03]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 20 io port: [0x00-0x0f]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 24 32bit mmio: [0x000000-0x0001ff]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: reg 30 32bit mmio: [0x000000-0x07ffff]
Sep  1 21:33:14 shambhala kernel: pci 0000:03:00.0: supports D1 D2
Sep  1 21:33:14 shambhala kernel: sata_sil 0000:03:00.0: enabling device (0000 -> 0003)
Sep  1 21:33:14 shambhala kernel: sata_sil 0000:03:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11
Sep  1 21:33:14 shambhala kernel: sata_sil 0000:03:00.0: cache line size not set.  Driver may not function
Sep  1 21:33:14 shambhala kernel: sata_sil 0000:03:00.0: Applying R_ERR on DMA activate FIS errata fix
Sep  1 21:33:14 shambhala kernel: sata_sil 0000:03:00.0: setting latency timer to 64
Sep  1 21:33:14 shambhala kernel: scsi8 : sata_sil
Sep  1 21:33:14 shambhala kernel: scsi9 : sata_sil
Sep  1 21:33:14 shambhala kernel: ata9: SATA max UDMA/100 mmio m512@0xc4000000 tf 0xc4000080 irq 11
Sep  1 21:33:14 shambhala kernel: ata10: SATA max UDMA/100 mmio m512@0xc4000000 tf 0xc40000c0 irq 11
Sep  1 21:33:14 shambhala kernel: ata9: SATA link down (SStatus 0 SControl 310)
Sep  1 21:33:14 shambhala kernel: ata10: SATA link down (SStatus 0 SControl 310)

(I inserted and removed it several times and get subsequent ata numbers, thus its at ata9 and ata10 for the two links now.)

shambhala:~> lspcmcia
Socket 0 Bridge:        [yenta_cardbus]         (bus ID: 0000:02:00.0)
  CardBus card -- see "lspci" for more information
Socket 1 Bridge:        [yenta_cardbus]         (bus ID: 0000:02:00.1)
shambhala:~> lspci -nn | egrep "Silicon|CardBus"
02:00.0 CardBus bridge [0607]: Texas Instruments PCI4520 PC card Cardbus Controller [104c:ac46] (rev 01)
02:00.1 CardBus bridge [0607]: Texas Instruments PCI4520 PC card Cardbus Controller [104c:ac46] (rev 01)
03:00.0 Mass storage controller [0180]: Silicon Image, Inc. SiI 3512 [SATALink/SATARaid] Serial ATA Controller [1095:3512] (rev 01)


I lost a mount on an external SATA drive due to this - so this means potential data loss! With 2.6.29 it was no problem to keep the externel SATA drive mounted during snapshot cycles. (If I leave it connected or connect it again prior to resuming that is.)


Expected behavior:
PCMCIA cards work after resuming. Such like with 2.6.29 and previous kernels.


syslog of a complete snapshot cycle on my T23:

martin@deepdance:~> grep "kernel" /var/log/syslog | grep -v chrony | tail -n160 -f
Sep  1 21:02:17 localhost kernel: parport_pc 00:0b: disabled                          
Sep  1 21:02:17 localhost kernel: serial 00:0a: disabled                              
Sep  1 21:02:17 localhost kernel: e100 0000:02:08.0: PCI INT A disabled               
Sep  1 21:02:17 localhost kernel: e100 0000:02:08.0: PME# enabled                     
Sep  1 21:02:17 localhost kernel: pci 0000:01:00.0: PCI INT A disabled                
Sep  1 21:02:17 localhost kernel: Intel ICH 0000:00:1f.5: PCI INT B disabled          
Sep  1 21:02:17 localhost kernel: ata_piix 0000:00:1f.1: PCI INT A disabled           
Sep  1 21:02:17 localhost kernel: ACPI: Preparing to enter system sleep state S4      
Sep  1 21:02:17 localhost kernel: PM: Saving platform NVS memory                      
Sep  1 21:02:17 localhost kernel: PM: Restoring platform NVS memory                   
Sep  1 21:02:17 localhost kernel: ACPI: Waking up from system sleep state S4          
Sep  1 21:02:17 localhost kernel: uhci_hcd 0000:00:1d.0: power state changed by ACPI to D0
Sep  1 21:02:17 localhost kernel: uhci_hcd 0000:00:1d.1: power state changed by ACPI to D0
Sep  1 21:02:17 localhost kernel: uhci_hcd 0000:00:1d.2: restoring config space at offset 0x1 (was 0x2800001, writing 0x2800005)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ata_piix 0000:00:1f.1: restoring config space at offset 0x1 (was 0x2800003, writing 0x2800007)                                                                                                                  
Sep  1 21:02:17 localhost kernel: Intel ICH 0000:00:1f.5: restoring config space at offset 0x1 (was 0x2800000, writing 0x2800001)                                                                                                                 
Sep  1 21:02:17 localhost kernel: pci 0000:01:00.0: restoring config space at offset 0x1 (was 0x2300007, writing 0x2300003)                                                                                                                       
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.0: restoring config space at offset 0xf (was 0x3c0010b, writing 0x500010b)                                                                                                             
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.0: restoring config space at offset 0x5 (was 0x20000a0, writing 0x220000a0)                                                                                                            
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.0: restoring config space at offset 0x3 (was 0x824008, writing 0x82a808)                                                                                                               
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.0: restoring config space at offset 0x1 (was 0x2100107, writing 0x2100007)                                                                                                             
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.1: restoring config space at offset 0xf (was 0x3c0020b, writing 0x5c0020b)                                                                                                             
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.1: restoring config space at offset 0x3 (was 0x824008, writing 0x82a808)                                                                                                               
Sep  1 21:02:17 localhost kernel: yenta_cardbus 0000:02:00.1: restoring config space at offset 0x1 (was 0x2100107, writing 0x2100007)                                                                                                             
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0xf (was 0xffffffff, writing 0x2a01010b)                                                                                                                
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0xe (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0xd (was 0xffffffff, writing 0x40)                                                                                                                      
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0xc (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0xb (was 0xffffffff, writing 0x351033)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x9 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x8 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x7 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x6 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x5 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x4 (was 0xffffffff, writing 0xc4000000)                                                                                                                
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x3 (was 0xffffffff, writing 0x804000)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x2 (was 0xffffffff, writing 0xc031043)                                                                                                                 
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x1 (was 0xffffffff, writing 0x2100006)                                                                                                                 
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: restoring config space at offset 0x0 (was 0xffffffff, writing 0x351033)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: PME# disabled                                                   
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0xf (was 0xffffffff, writing 0x2a01020b)                                                                                                                
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0xe (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0xd (was 0xffffffff, writing 0x40)                                                                                                                      
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0xc (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0xb (was 0xffffffff, writing 0x351033)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x9 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x8 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x7 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x6 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x5 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x4 (was 0xffffffff, writing 0xc4001000)                                                                                                                
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x3 (was 0xffffffff, writing 0x4000)                                                                                                                    
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x2 (was 0xffffffff, writing 0xc031043)                                                                                                                 
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x1 (was 0xffffffff, writing 0x2100006)                                                                                                                 
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: restoring config space at offset 0x0 (was 0xffffffff, writing 0x351033)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: PME# disabled                                                   
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0xf (was 0xffffffff, writing 0x2210030b)                                                                                                                
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0xe (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0xd (was 0xffffffff, writing 0x40)                                                                                                                      
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0xc (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0xb (was 0xffffffff, writing 0x10741838)                                                                                                                
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x9 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x8 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x7 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x6 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x5 (was 0xffffffff, writing 0x0)                                                                                                                       
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x4 (was 0xffffffff, writing 0xc4002000)                                                                                                                
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x3 (was 0xffffffff, writing 0x4408)                                                                                                                    
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x2 (was 0xffffffff, writing 0xc032004)                                                                                                                 
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x1 (was 0xffffffff, writing 0x2100016)                                                                                                                 
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: restoring config space at offset 0x0 (was 0xffffffff, writing 0xe01033)                                                                                                                  
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: PME# disabled                                                   
Sep  1 21:02:17 localhost kernel: pm_op(): pci_pm_restore+0x0/0xe0 returns -16                                           
Sep  1 21:02:17 localhost kernel: PM: Device 0000:00:00.0 failed to restore: error -16                                   
Sep  1 21:02:17 localhost kernel: uhci_hcd 0000:00:1d.0: setting latency timer to 64                                     
Sep  1 21:02:17 localhost kernel: usb usb1: root hub lost power or was reset                                             
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: HC died; cleaning up                                            
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: HC died; cleaning up                                            
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: HC died; cleaning up                                            
Sep  1 21:02:17 localhost kernel: uhci_hcd 0000:00:1d.1: setting latency timer to 64                                     
Sep  1 21:02:17 localhost kernel: usb usb2: root hub lost power or was reset                                             
Sep  1 21:02:17 localhost kernel: uhci_hcd 0000:00:1d.2: setting latency timer to 64                                     
Sep  1 21:02:17 localhost kernel: usb usb3: root hub lost power or was reset                                             
Sep  1 21:02:17 localhost kernel: pci 0000:00:1e.0: setting latency timer to 64                                          
Sep  1 21:02:17 localhost kernel: ata_piix 0000:00:1f.1: PCI INT A -> Link[LNKC] -> GSI 11 (level, low) -> IRQ 11        
Sep  1 21:02:17 localhost kernel: ata_piix 0000:00:1f.1: setting latency timer to 64                                     
Sep  1 21:02:17 localhost kernel: Intel ICH 0000:00:1f.5: PCI INT B -> Link[LNKB] -> GSI 11 (level, low) -> IRQ 11       
Sep  1 21:02:17 localhost kernel: Intel ICH 0000:00:1f.5: setting latency timer to 64                                    
Sep  1 21:02:17 localhost kernel: pci 0000:01:00.0: PME# disabled                                                        
Sep  1 21:02:17 localhost kernel: pci 0000:01:00.0: PCI INT A -> Link[LNKA] -> GSI 11 (level, low) -> IRQ 11             
Sep  1 21:02:17 localhost kernel: ata1.00: ACPI cmd ef/02:00:00:00:00:a0 succeeded                                       
Sep  1 21:02:17 localhost kernel: ata1.00: ACPI cmd f5/00:00:00:00:00:a0 filtered out                                    
Sep  1 21:02:17 localhost kernel: ata1.00: ACPI cmd ef/03:45:00:00:00:a0 filtered out                                    
Sep  1 21:02:17 localhost kernel: ata1.00: ACPI cmd ef/03:0c:00:00:00:a0 filtered out                                    
Sep  1 21:02:17 localhost kernel: ata1.00: configured for UDMA/100                                                       
Sep  1 21:02:17 localhost kernel: ata2.00: ACPI cmd ef/03:42:00:00:00:a0 filtered out                                    
Sep  1 21:02:17 localhost kernel: ata2.00: ACPI cmd ef/03:0c:00:00:00:a0 filtered out                                    
Sep  1 21:02:17 localhost kernel: ata1.00: configured for UDMA/100                                                       
Sep  1 21:02:17 localhost kernel: ata1: EH complete                                                                      
Sep  1 21:02:17 localhost kernel: ata2.00: ACPI cmd e3/00:1f:00:00:00:a0 succeeded                                       
Sep  1 21:02:17 localhost kernel: ata2.00: ACPI cmd e3/00:02:00:00:00:a0 succeeded                                       
Sep  1 21:02:17 localhost kernel: ata2.00: configured for UDMA/33                                                        
Sep  1 21:02:17 localhost kernel: pci 0000:02:02.0: PME# disabled                                                        
Sep  1 21:02:17 localhost kernel: e100 0000:02:08.0: PME# disabled                                                       
Sep  1 21:02:17 localhost kernel: serial 00:0a: activated                                                                
Sep  1 21:02:17 localhost kernel: parport_pc 00:0b: activated                                                            
Sep  1 21:02:17 localhost kernel: sd 0:0:0:0: [sda] Starting disk                                                        
Sep  1 21:02:17 localhost kernel: usb 1-1: reset full speed USB device using uhci_hcd and address 2                      
Sep  1 21:02:17 localhost kernel: snd-usb-audio 1-1:1.0: no reset_resume for driver snd-usb-audio?                       
Sep  1 21:02:17 localhost kernel: snd-usb-audio 1-1:1.1: no reset_resume for driver snd-usb-audio?                       
Sep  1 21:02:17 localhost kernel: snd-usb-audio 1-1:1.2: no reset_resume for driver snd-usb-audio?                       
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.0: PME# disabled                                                   
Sep  1 21:02:17 localhost kernel: ohci_hcd 0000:03:00.1: PME# disabled                                                   
Sep  1 21:02:17 localhost kernel: ehci_hcd 0000:03:00.2: PME# disabled                                                   
Sep  1 21:02:17 localhost kernel: Post atomic.
Sep  1 21:02:17 localhost kernel: Reading caches...
Sep  1 21:02:17 localhost kernel: ...20%...40%...60%...80%...100%
Sep  1 21:02:17 localhost kernel: Waited for i/o due to throughput_throttle 378 times.
Sep  1 21:02:17 localhost kernel: Cleaning up...
Sep  1 21:02:17 localhost kernel: Restarting all filesystems ...
Sep  1 21:02:17 localhost kernel: Restarting tasks ...
Sep  1 21:02:17 localhost kernel: usb 5-1: USB disconnect, address 2
Sep  1 21:02:17 localhost kernel: Restarting tasks ... done.
Sep  1 21:02:17 localhost kernel: TuxOnIce debugging info:
Sep  1 21:02:17 localhost kernel: - TuxOnIce core  : 3.0.1
Sep  1 21:02:17 localhost kernel: - Kernel Version : 2.6.31-rc7-tp23-toi-3.0.1-04741-g57e61c0
Sep  1 21:02:17 localhost kernel: - Compiler vers. : 4.3
Sep  1 21:02:17 localhost kernel: - Attempt number : 1
Sep  1 21:02:17 localhost kernel: - Parameters     : 0 667656 0 1 0 0
Sep  1 21:02:17 localhost kernel: - Overall expected compression percentage: 0.
Sep  1 21:02:17 localhost kernel: - Checksum method is 'md4'.
Sep  1 21:02:17 localhost kernel:  0 pages resaved in atomic copy.
Sep  1 21:02:17 localhost kernel: - Compressor is 'lzo'.
Sep  1 21:02:17 localhost kernel:  Compressed 403554304 bytes into 196430568 (51 percent compression).
Sep  1 21:02:17 localhost kernel: - Max outstanding reads 766. Max writes 6.
Sep  1 21:02:17 localhost kernel:  Memory_needed: 1024 x (4096 + 200 + 76) = 4476928 bytes.
Sep  1 21:02:17 localhost kernel:  Free mem throttle point reached 0.
Sep  1 21:02:17 localhost kernel: - SwapAllocator active.
Sep  1 21:02:17 localhost kernel:  Swap available for image: 244496 pages.
Sep  1 21:02:17 localhost kernel: - FileAllocator inactive.
Sep  1 21:02:17 localhost kernel: - I/O speed: Write 27 MB/s, Read 34 MB/s.
Sep  1 21:02:17 localhost kernel: - Extra pages    : 2 used/500.
Sep  1 21:02:17 localhost kernel: - Result         : Succeeded.
Sep  1 21:02:18 localhost kernel: IBM TrackPoint firmware: 0x0e, buttons: 3/3
Sep  1 21:02:18 localhost kernel: input: TPPS/2 IBM TrackPoint as /class/input/input10
Sep  1 21:02:18 localhost kernel: XFS mounting filesystem sda6
Sep  1 21:02:18 localhost kernel: Ending clean XFS mount for filesystem: sda6
Sep  1 21:02:52 localhost kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
Sep  1 21:02:54 localhost kernel: e100: eth0 NIC Link is Up 100 Mbps Full Duplex
Sep  1 21:02:54 localhost kernel: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Sep  1 21:03:05 localhost kernel: eth0: no IPv6 routers present
Sep  1 21:04:26 localhost kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
Sep  1 21:04:28 localhost kernel: e100: eth0 NIC Link is Up 100 Mbps Full Duplex
Sep  1 21:04:28 localhost kernel: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Sep  1 21:04:33 localhost kernel: device eth0 entered promiscuous mode
Sep  1 21:04:33 localhost kernel: device eth0 left promiscuous mode
Sep  1 21:04:38 localhost kernel: eth0: no IPv6 routers present
Comment 1 Martin Steigerwald 2009-09-01 19:46:08 UTC
Created attachment 22955 [details]
config for kernel that works okay on my ThinkPad T42
Comment 2 Martin Steigerwald 2009-09-01 19:47:17 UTC
Created attachment 22956 [details]
config for latest kernel that doesn't work on ThinkPad T42

I can dig out the config for the 2.6.31-rc5 kernel as well, but its pretty similar.
Comment 3 Martin Steigerwald 2009-09-01 19:48:43 UTC
Created attachment 22957 [details]
config for kernel that works okay on my ThinkPad T23
Comment 4 Martin Steigerwald 2009-09-01 19:49:28 UTC
Created attachment 22958 [details]
config for first kernel that didn´t work on my ThinkPad T23
Comment 5 Martin Steigerwald 2009-09-01 19:50:25 UTC
Created attachment 22959 [details]
config for recent kernel that doesn't work on my ThinkPad T23

2.6.31-rc5 and 2.6.31-rc7 should be configured pretty similar.
Comment 6 Andrew Morton 2009-09-03 22:10:02 UTC
Rafael, any suggestions as to which subsystem we can thank for thsi regression?
Not PCMCIA, I'd expect - hardly anything is getting changed in there nowadays.

Thanks.

(I marked this as a regression)
Comment 7 Rafael J. Wysocki 2009-09-03 22:41:05 UTC
Let's assign it to hibernation/suspend for now.

Martin, any chance to verify whether or not 2.6.30 was OK?
Comment 8 Martin Steigerwald 2009-09-04 09:36:19 UTC
Difficult, as TuxOnIce didn't work with 2.6.30[1]. I also tried in kernel suspend with a 2.6.30 kernel of mine and a Debian Kernel AFAIR and it didn't work either - it was a very quick test however and maybe it was misconfigured. I could try whether userspace sws works with 2.6.31 - if it does and it still doesn't work with 2.6.30 it would seem to me that 2.6.30 is broken for me regarding hibernation. If userspace sws works with 2.6.30 I could try this. I could try to get TuxOnIce to work on 2.6.30 or find out why it doesn't work, but I tried this hard before and it has become quite a time sink[1]. Or I could have a look whether the pcmcia card bug also happens with suspend to RAM and maybe suspend to RAM does work with 2.6.30.

Well I can try a lot of things, but to avoid this becoming a time sink I would like to  know where to spend my efforts most efficiently. Do you have any idea? Would trying with suspend to RAM help to narrow this down? I am quite clueless ATM. Is there any way to get some debug output?

[1] http://lists.tuxonice.net/lurker/message/20090617.200943.f5eea8fe.en.html
(I don't think lurker shows the complete thread)
Comment 9 Rafael J. Wysocki 2009-09-04 14:22:49 UTC
I think it would be better to focus on suspend to RAM first.

If possible, please check if suspend to RAM works with the current Linus' tree and if it doesn't, what's the last known major kernel release it works with.
Comment 10 Zhang Rui 2009-10-15 08:14:13 UTC
close this bug as there is no response from the bug reporter for more than a month.
please reopen it if
1. the problem still exists in 2.6.31 kernel
2. you can provide the info requested in comment #9.
Comment 11 Martin Steigerwald 2009-10-25 08:58:32 UTC
Sorry, I tried Suspend to RAM but this didn't work at all on my ThinkPad T23.

At least for my ThinkPad T23 appears to have been fixed in

martin@deepdance:~> cat /proc/version
Linux version 2.6.31.3-tp23-toi-3.0.1-04847-gd9af9b3 (martin@deepdance) (gcc version 4.3.4 (Debian 4.3.4-2) ) #2 PREEMPT Fri Oct 9 19:57:41 CEST 2009

or in some updated userspace component (doubt this). Didn't test for my T42 yet. Will reopen if necessary.
Comment 12 Rafael J. Wysocki 2009-10-25 21:55:05 UTC
Hmm, I think this is a duplicate of bug #13092.

*** This bug has been marked as a duplicate of bug 13092 ***