**** BEGIN LOGGING AT Sat Jun 05 02:59:57 2010
Jun 05 03:30:47 <holtmann> ofonod[15864]: 1st:> AT+CGDATA="PPP",1\r
Jun 05 03:30:48 <holtmann> ofonod[15864]: 1st:< \r\nCONNECT HSDPA 7.2\r\n
Jun 05 03:30:48 <holtmann> L	Ġ

Jun 05 03:30:48 <holtmann> L	ĠEntering new phase: 1
Jun 05 03:30:49 <holtmann> Entering new phase: 2
Jun 05 03:30:49 <holtmann> Entering new phase: 3
Jun 05 03:30:52 <holtmann> Received IPCP NAK
Jun 05 03:30:59 <holtmann> We are having some fun with debug pointers.
Jun 05 03:32:35 <holtmann> Entering new phase: 5
Jun 05 03:32:35 <holtmann> Entering new phase: 0
Jun 05 03:32:35 <holtmann> ofonod[15878]: 1st:< \r\nNO CARRIER\r\n
Jun 05 03:32:35 <holtmann> ofonod[15878]: 2nd:< \r\nNO CARRIER\r\n
Jun 05 03:32:37 <holtmann> ^Cofonod[15878]: Example Network Time Remove for modem: 0xa3c750
Jun 05 03:32:37 <holtmann> ofonod[15878]: Example History Remove for modem: 0xa3c750
Jun 05 03:32:39 <holtmann> (ofonod:15878): GLib-CRITICAL **: g_io_add_watch_full: assertion `channel != NULL' failed
Jun 05 03:32:40 <holtmann> ofonod[15878]: Exit
Jun 05 03:32:43 <holtmann> denkenz: And do you have an idea with this one?
Jun 05 03:47:45 <denkenz> holtmann: Nope
Jun 05 03:48:21 <denkenz> that happens pretty late in the game, not even sure who'd be adding io watches at that point
Jun 05 03:54:29 <holtmann> It happens when I ctrl-c the daemon.
Jun 05 03:54:44 <denkenz> I just ctrl-ced the daemon, worked fine
Jun 05 03:54:45 <holtmann> However it only happens when I activated the context.
Jun 05 03:54:55 <holtmann> If I never activated the context everything is fine.
Jun 05 03:55:12 <denkenz> so probably ppp code
Jun 05 03:56:02 <holtmann> I have GPRS, SMS, netreg and everything else on 2nd port. On 1st is only devinfo, SIM and GPRS-context.
Jun 05 03:56:10 <holtmann> That way the CREG hack is no longer needed.
Jun 05 03:56:41 <denkenz> shouldn't gprs-context only be on the 1st port?
Jun 05 03:56:48 <denkenz> and the rest on 2nd?
Jun 05 03:58:31 <holtmann> Lets see.
Jun 05 03:58:45 <denkenz> Anyway, this is coming from the ppp resume code
Jun 05 03:58:54 <denkenz> seems the io channel got hung up
Jun 05 04:00:04 <denkenz> put a debug in the beginning & end of g_at_io_set_write_handler
Jun 05 04:00:10 <denkenz> to see if I'm right
Jun 05 04:00:17 <holtmann>     [ /356846015115701/operator/Unknow ]
Jun 05 04:00:17 <holtmann>         Status = available
Jun 05 04:00:17 <holtmann>         Technologies = umts 
Jun 05 04:00:17 <holtmann>         MobileNetworkCode = now
Jun 05 04:00:18 <holtmann>         Name = Unknown
Jun 05 04:00:18 <holtmann>         MobileCountryCode = Unk
Jun 05 04:00:28 <holtmann> Yikes. Something went wrong here.
Jun 05 04:00:38 <denkenz> what in the world?
Jun 05 04:00:52 <denkenz> that's unpossible
Jun 05 04:01:11 <holtmann> ofonod[16051]: 2nd:> AT+COPS?\r
Jun 05 04:01:12 <holtmann> ofonod[16051]: 1st:< \r\n+CREG: 2,,\r\n\r\n+CGREG: 2,,\r\n
Jun 05 04:01:12 <holtmann> ofonod[16051]: 2nd:< \r\n+CREG: 2,,\r\n\r\n+CGREG: 2,,\r\n
Jun 05 04:01:12 <holtmann> ofonod[16051]: 2nd:< \r\n+COPS: 0,2,"Unknown",2\r\n\r\nOK\r\n
Jun 05 04:01:13 <holtmann> ofonod[16051]: 2nd:> AT+COPS=3,0\r
Jun 05 04:01:13 <holtmann> ofonod[16051]: 2nd:< \r\nOK\r\n
Jun 05 04:01:16 <holtmann> ofonod[16051]: 2nd:> AT+COPS?\r
Jun 05 04:01:16 <holtmann> ofonod[16051]: 2nd:< \r\n+COPS: 0,0,"Unknown",2\r\n\r\nOK\r\n
Jun 05 04:01:24 <denkenz> boggle
Jun 05 04:01:44 <denkenz> Do me a favor, unplug the modem and throw it out of the window
Jun 05 04:03:33 <holtmann> I am on the 18 floor. Could hurt someone ;)
Jun 05 04:04:36 <denkenz> ok, I will make the core ignore the cops callback if we're in unregistered state
Jun 05 04:20:42 <holtmann> Pushed my changes.
Jun 05 04:22:12 <holtmann> Any idea with GIOChannel watch issue. I have no idea where to look.
Jun 05 04:22:29 <denkenz> [22:58] <denkenz> Anyway, this is coming from the ppp resume code
Jun 05 04:22:30 <denkenz> [22:58] <denkenz> seems the io channel got hung up
Jun 05 04:22:31 <denkenz> [23:00] <denkenz> put a debug in the beginning & end of g_at_io_set_write_handler
Jun 05 04:22:33 <denkenz> [23:00] <denkenz> to see if I'm right
Jun 05 04:22:59 <holtmann> Hah. Missed that. Let me check.
Jun 05 04:25:37 <holtmann> Entering new phase: 4
Jun 05 04:25:38 <holtmann> io 0x255bba0
Jun 05 04:25:38 <holtmann> done
Jun 05 04:25:38 <holtmann> Entering new phase: 5
Jun 05 04:25:40 <holtmann> Entering new phase: 0
Jun 05 04:25:40 <holtmann> ofonod[16710]: 1st:< \r\nNO CARRIER\r\n
Jun 05 04:25:42 <holtmann> ofonod[16710]: 2nd:< \r\nNO CARRIER\r\n
Jun 05 04:25:43 <holtmann> ^Cofonod[16710]: Example Network Time Remove for modem: 0x25647c0
Jun 05 04:25:45 <holtmann> ofonod[16710]: Example History Remove for modem: 0x25647c0
Jun 05 04:25:47 <holtmann> io 0x2564d20
Jun 05 04:25:49 <holtmann> io 0x255bba0
Jun 05 04:25:50 <holtmann> (ofonod:16710): GLib-CRITICAL **: g_io_add_watch_full: assertion `channel != NULL' failed
Jun 05 04:25:55 <holtmann> done
Jun 05 04:25:56 <denkenz> heh
Jun 05 04:25:57 <holtmann> io 0x255bba0
Jun 05 04:25:58 <holtmann> ofonod[16710]: Exit
Jun 05 04:27:01 <denkenz> so sounds like your Novatel modem also hups on a no carrier
Jun 05 04:27:32 <holtmann> It was fine, when I had it on the 2nd TTY.
Jun 05 04:28:07 <denkenz> Probably because the 2nd tty shouldn't be used for ppp
Jun 05 04:28:22 <denkenz> On my Huawei the 2nd tty is the PCUI port
Jun 05 04:28:27 <denkenz> 1st is the Modem port
Jun 05 04:28:42 <holtmann> Maybe.
Jun 05 04:32:30 <holtmann> So the Qualcomm chip itself is a piece of crap actually.
Jun 05 04:50:07 <denkenz> put a debug in read_watcher_destroy_notify to confirm, but I suspect that's the issue
Jun 05 04:50:25 <denkenz> In which case we need to solve port re-opening for Huawei & Novatel
Jun 05 04:55:48 <holtmann> Entering new phase: 0
Jun 05 04:55:48 <holtmann> ofonod[17668]: 1st:< \r\nNO CARRIER\r\n
Jun 05 04:55:48 <holtmann> ofonod[17668]: 2nd:< \r\nNO CARRIER\r\n
Jun 05 04:55:48 <holtmann> xxx
Jun 05 04:56:11 <denkenz> so it hups
Jun 05 04:57:43 <holtmann> :(
Jun 05 04:58:22 <denkenz> well we need to solve it anyway
Jun 05 04:58:36 <denkenz> Sounds like this will be an issue with novatel / huawei / sierra modems anyway
Jun 05 05:00:41 <denkenz> I have some fixes for COPS, but I need to do some testing before I push
Jun 05 05:02:34 <holtmann> So in theory we need to close the device and re-open it.
Jun 05 05:14:26 <holtmann> What is the disconnect callback for? It doesn't trigger on HUP?
Jun 05 08:20:43 <padovan> denkenz: ping
Jun 05 08:21:36 <padovan> denkenz: oFono doesn't support ITU V.250 today, right?
Jun 05 08:22:05 <padovan> denkenz: where in the sources should I put my DUN client daemon?
Jun 05 14:50:49 <denkenz> holtmann: It does
Jun 05 14:51:14 <denkenz> holtmann: however, there is a race, ppp sets the disconnect callback and uses it to detect the dead channel
Jun 05 14:51:22 <denkenz> holtmann: We currently treat it as a ppp disconnect
Jun 05 14:51:39 <denkenz> holtmann: GAtChat can also detect it, but we don't do so today
Jun 05 14:52:01 <denkenz> As in gprs context doesn't set the disconnect function
Jun 05 14:52:33 <denkenz> at the point that io disconnect fired, the device is closed, so yes we need to re-open
Jun 05 14:52:44 <denkenz> padovan: We support V250, see gatchat/gatserver.c
Jun 05 14:52:54 <denkenz> padovan: For now put it in dun/
**** ENDING LOGGING AT Sun Jun 06 02:59:56 2010