Can you grab /var/log/messages at the time the reconnect failure occurs?  Thanks!

Comment on attachment 414572 [details]
/var/log/messages: two failed attempts, followed by killall modem-manager, followed by success

Fixing MIME type of my /var/log/messages attachment.

Dan, I am sorry if I misunderstood, but isn't this attachment what you
are asking for?

Yeah, I suck.  So now to debug modem-manager, can you:

1) service NetworkManager stop
2) killall -TERM modem-manager
3) modem-manager --debug
4) service NetworkManager start

and then try to reproduce the problem.  When you can, attach the 'modem-manager --debug' output and we can see whats going on in NM.  Thanks!

Created attachment 415795 [details]
Output of modem-manager --debug

# service NetworkManager stop
Stopping NetworkManager daemon:                            [  OK  ]
# killall -TERM modem-manager
# killall -TERM modem-manager
modem-manager: no process killed
# modem-manager --debug > mmlog  2>&1
# service NetworkManager start
Setting network parameters...                              [  OK  ]
Starting NetworkManager daemon:                            [  OK  ]


Then I inserted the card and connected via NetworkManager; here is the
end of the part of the log that covers the successfull connection:

** (modem-manager:3311): DEBUG: (noz0): --> 'ATD*99***-1#<CR>'
** (modem-manager:3311): DEBUG: (noz0): <-- '<CR><LF>CONNECT 1800000<CR><LF>'
** Message: Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected)
** (modem-manager:3311): DEBUG: (net/ppp0): could not get port's parent device
** Message: Modem /org/freedesktop/ModemManager/Modems/0: state changed (connected -> disconnecting)
** (modem-manager:3311): DEBUG: (noz0): --> 'AT+CGACT=0<CR>'
** Message: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disconnecting -> registered)
** (modem-manager:3311): DEBUG: (noz0): --> 'AT+CSQ<CR>'
** (modem-manager:3311): DEBUG: (noz0): <-- '<CR><LF>+CSQ: 0,99<CR><LF><CR><LF>OK<CR><LF>'

Then I suspended to RAM and woke up after some minutes and tried to
establish the same connection via NetworkManager again for three times.
Each of the connection attempts failed "immediately".

Then I started ModemManager again, as above, alas there was still a
process running, so I first had to kill that (and actually stop
NetworkManager for a "permanent" kill) and indeed I could establish
a connection again.

I hope this is what you're looking for?

Do you have any of the modem-manager --debug from across the suspend/resume?  Since nozomi is a PCI driver it may be that it doesn't add/remove the device across suspend and thus MM is keeping the device open an expecting it to still be available on resume, when the driver is clearly not ready yet.  Having the --debug logs after resume might tell us whether that's the case.

So I"ve tested nozomi over suspend/resume on F11 and the driver appears to believe nothing has happened.  MM ends up sending a command which may or may not time out  but eventually (like 5 seconds) the device begins to respond.  Seamless suspend/resume like what nozomi currently does is actually the desirable way, but the fact that the card doesn't respond for a bit isnt' desirable.  It may be that the card is booting back up internally at resume time and thus unable to accept commands at that time.

Lets get some logs from your machine and see what's going on there.

If you wait a few seconds does stuff begin to work, or does it simply not work no matter how  long you wait?

(In reply to comment #6)
> If you wait a few seconds does stuff begin to work, or does it simply
> not work no matter how  long you wait?

The latter.  I'm pretty sure I have tried waiting for (quite more than)
five seconds regularily.

Created attachment 416243 [details]
Output of modem-manager --debug on Fedora 13 (look for comments "Gerald:")

(In reply to comment #5)
> Do you have any of the modem-manager --debug from across the suspend/resume?

Yes, actually the log I attached in comment #4 should provide that. ;-)
Apologies for the description there not being really clear, though.

Line 138 is where the successful connection ends; you can see how I
disconnected via NetworkManager.  Everything between that part and
line 210 are failed connection attempts.


Now, over the weekend I upgrade the machine from Fedora 12 to 13, so
I figured I'd give it another try.  Attaching output from modem-manager
--debug for the following steps:

 1. two successful sequences of connect/disconnect via NM
 2. card is removed and inserted again
 3. card shows up in NM
 4. connection attempt in NM leads takes a while until it fails
 5. second attempt fails similarily
 6. killed modem-manager, and restarted again; hmm, no luck with NM:
    card shows up, but connection attempts fail immediately (different
    from steps 4, but similar to the original report in this bug)
 7. now stopped NM, then killed modem-manager, started again, and
    restarted NM; still no luck, as in step 6.

(The following two steps are not in the log.)

 8. removing and inserting card leads to behavior in step 4 again.
 9. killall modem-manager eventually leads to a connection

One more things: please note that in my test around suspend-to-ram, I did
remove the card before suspending and inserted it again after resuming.

(Looks like a common use case, since leaving the card attached when putting
the notebook into a bag pretty likely would break it. ;-)

Ok, the modem-manager log doesn't look too interesting, everything looks pretty much OK there.  So when NM fails to connect (*after* MM has run the ATD and you get CONNECT 1800000) that usually indicates a PPP failure.  You can debug this by stopping NM and running it like so:

sudo NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --debug

then reproducing the problem and then attaching that output to this bug.

This turns on PPP debugging and lets us figure out why the PPP connection appears to be failing even though the modem starts the data session just fine.

I did run into this once the other day; pppd simply couldn't negotiate options with the remote peer for some reason.

Hmm,  NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --debug  gave me
  Invalid option.  Please use --help to see a list of valid options.
did you mean the following?
  NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --log-level=debug


Here is what I did:

 0. boot ; service NetworkManager stop; killall modem-manager
 1. NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --log-level=debug
 2. insert card
 3. initiate connection via nm-applet; works lovely
 4. suspend to RAM; wait for 30s; resume
 5. initiate connection via nm-applet; fails a couple of times
 6. wait a minute and try again; still fails instantaneously
 7. remove card; wait a couples; insert again
 8. initiate connection via nm-applet; works lovely
 9. disconnect; reconnect; works lovely
 a. suspend to RAM; wait for 1'; resume
 b. initiate connection via nm-applet; fails twice
 c. killall modem-manager
 d. initiate connection via nm-applet; works lovely
 e. confirm the above (twice):
     suspend
     resume
     connection fails
     killall modem-manager
     connection succeeds

Now, to make this more interesting, _some_ of the resumes apparently
ran into a kernel oops (but the system continued working nicely).

(I also submitted this via aport, just don't see it in Bugzilla yet.)

------------[ cut here ]------------
WARNING: at fs/fs-writeback.c:597 writeback_inodes_wb+0x229/0x380()
Hardware name: 2768DR7
Modules linked in: ppp_deflate zlib_deflate ppp_async crc_ccitt ppp_generic slhc nozomi nls_utf8 fuse nfsd lockd nfs_acl auth_rpcgss sunrpc cpufreq_ondemand acpi_cpufreq freq_table ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 xfs exportfs uinput arc4 snd_hda_codec_conexant snd_hda_intel snd_hda_codec ecb snd_hwdep snd_seq iwlagn snd_seq_device iwlcore snd_pcm snd_timer mac80211 thinkpad_acpi e1000e snd snd_page_alloc cfg80211 soundcore wmi iTCO_wdt iTCO_vendor_support rfkill i2c_i801 microcode joydev sha256_generic aes_x86_64 aes_generic cbc dm_crypt firewire_ohci yenta_socket rsrc_nonstatic firewire_core crc_itu_t i915 drm_kms_helper drm i2c_algo_bit i2c_core video output [last unloaded: scsi_wait_scan]
Pid: 1890, comm: flush-253:0 Tainted: G        W  2.6.33.4-95.fc13.x86_64 #1
Call Trace:
[<ffffffff8104b558>] warn_slowpath_common+0x77/0x8f
[<ffffffff8104b57f>] warn_slowpath_null+0xf/0x11
[<ffffffff8111c3a7>] writeback_inodes_wb+0x229/0x380
[<ffffffff8111c63b>] wb_writeback+0x13d/0x1bc
[<ffffffff8109e283>] ? call_rcu_sched+0x10/0x12
[<ffffffff8109e28e>] ? call_rcu+0x9/0xb
[<ffffffff8111c7cf>] wb_do_writeback+0x69/0x14d
[<ffffffff8111c8ed>] bdi_writeback_task+0x3a/0xaa
[<ffffffff810d5cf8>] ? bdi_start_fn+0x0/0xd4
[<ffffffff810d5d64>] bdi_start_fn+0x6c/0xd4
[<ffffffff810d5cf8>] ? bdi_start_fn+0x0/0xd4
[<ffffffff810643c7>] kthread+0x7a/0x82
[<ffffffff8100a924>] kernel_thread_helper+0x4/0x10
[<ffffffff8106434d>] ? kthread+0x0/0x82
[<ffffffff8100a920>] ? kernel_thread_helper+0x0/0x10

Created attachment 417922 [details]
/var/log/messages for comment #11 (NetworkManager --log-level=debug)

Sorry!  I meant:

sudo NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --log-level=debug --no-daemon

the no-daemon makes NM stay in the foreground.

Created attachment 426094 [details]
Output of sudo NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --log-level=debug --no-daemon

This provided the requested log.  Sorry, did take me a bit to manage
to work on this again.  (I had hoped the log from comment #11 would
be equivalent).

Some notes on the actions behind this log:

- A couple of unsuccessful events, for some reasons even a presumably
  virgin system did not work.

- Then a successful connection and use of the UMTS connection for a
  couple of minutes.

- Disconnect via nm-applet, suspend-to-RAM, waiting at last 30".

- Two failing attempts to connect via nm-applet (select the connection in
  the menu and the connection attempt stop immediately), waiting at least
  30", another failing attempt, and after a bit another one.

- killall modem-manager

- Wait until the menu item in nm-applet and, voila, connection works.

This message is a reminder that Fedora 12 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 12.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '12'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 12's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 12 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Still happening in Fedora 13; moving from 12 to 13 to prevent auto-closing.

This message is a reminder that Fedora 13 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 13.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '13'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 13's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 13 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Fedora 13 changed to end-of-life (EOL) status on 2011-06-25. Fedora 13 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.

Still happening in RHEL6.4 Beta for that matter using an Ericsson F5521gw Mobile Broadband Network Adapter. Always have to kill modem-manager after a resume to make it work again...