Ticket #567 (closed defect: fixed)
gta02 resumes immediately after flow control introduction, patch attached
| Reported by: | PaulFertser | Owned by: | mickey |
|---|---|---|---|
| Priority: | major | Milestone: | |
| Component: | cornucopia/fsogsm | Version: | milestone5.5 |
| Keywords: | Cc: |
Description
Attachments
Change History
Changed 3 years ago by PaulFertser
- Attachment 0001-fsogsmd-fix-suspend-resume-issue-surfaced-after-intr.patch added
comment:1 Changed 3 years ago by PaulFertser
There's another oddity though: sometimes one of the suspend commands hangs forever (so the phone is not suspended and i checked that flowcontrol reads 0 after that lack of answer).
Also waking up by an incoming sms message was of no good:
[INFO] libfsotransport <0710:3>: SRC: "+CREG=2" -> [ "07919730071111F10414D04937BD2C7797E9D3E61400 000160721092956105F4F29C1E03", "OK" ]
Apparently some initial portion was lost somehow, bad magic happens :/
comment:2 Changed 3 years ago by PaulFertser
stracing ftw
01:10:12 write(21, "2010-07-07T21:10:12.157141Z [DEBUG] libfsotransport <0710:3>: Wrote '%CNIV=0'. Waiting for answer...\n", 101) = 101
01:10:12 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 1 ([{fd=29, revents=POLLIN}])
01:10:12 read(29, "~\r\357\r\nOK\r\n5~", 4095) = 11
01:10:12 gettimeofday({1278537012, 195121}, NULL) = 0
01:10:12 write(21, "2010-07-07T21:10:12.195121Z [INFO] libfsotransport <0710:3>: SRC: \"%CNIV=0\" -> [ \"OK\" ]\n", 89) = 89
01:10:12 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:12 write(1, "** (process:24427): DEBUG: plugin.vala:117: lowlevel_openmoko_suspend()\n", 72) = 72
01:10:12 open("/sys/bus/platform/devices/neo1973-pm-gsm.0/flowcontrolled", O_WRONLY) = 36
01:10:12 write(36, "1", 1) = 1
01:10:12 close(36) = 0
01:10:12 gettimeofday({1278537012, 254739}, NULL) = 0
01:10:12 write(15, "2010-07-07T21:10:12.254739Z [DEBUG] FsoGsmGenericWatchDog <P:|KR:true>: onModemStatusChange FSO_GSM_MODEM_STATUS_SUSPENDING -> FSO_GSM_MODEM_STATUS_SUSPENDED\n", 158) = 158
01:10:12 writev(5, [{"l\4\1\1\16\0\0\0&\0\0\0o\0\0\0\1\1o\0\36\0\0\0/org/freesmartphone/GSM/Device\0\0\2\1s\0\35\0\0\0org.freesmartphone.GSM.Device\0\0\0\3\1s\0\f\0\0\0DeviceStatus\0\0\0\0\10\1g\0\1s\0\0", 128}, {"\t\0\0\0suspended\0", 14}], 2) = 142
01:10:12 gettimeofday({1278537012, 301397}, NULL) = 0
01:10:12 write(8, "2010-07-07T21:10:12.301397Z [INFO] TiCalypsoModem <4C>: Modem Status changed to FSO_GSM_MODEM_STATUS_SUSPENDED\n", 112) = 112
01:10:12 gettimeofday({1278537012, 326359}, NULL) = 0
01:10:12 write(4, "2010-07-07T21:10:12.326359Z [INFO] DBusServiceDevice <>: Modem suspended successfully\n", 87) = 87
01:10:12 writev(5, [{"l\2\1\1\0\0\0\0'\0\0\0\30\0\0\0\6\1s\0\5\0\0\0:1.87\0\0\0\5\1u\0H\2\0\0", 40}, {"", 0}], 2) = 40
01:10:12 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:12 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, -1) = 1 ([{fd=5, revents=POLLIN}])
01:10:12 read(5, "l\4\1\1<\0\0\0I\2\0\0\206\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\17\0\0\0ResourceChanged\0\10\1g\0\7sba{sv}\0\0\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\3\0\0\0GSM\0\0\0\0\0,\0\0\0\6\0\0\0policy\0\1i\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0refcount\0\1i\0\1\0\0\0", 2048) = 212
01:10:12 read(5, 0x2a9d8, 2048) = -1 EAGAIN (Resource temporarily unavailable)
01:10:12 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:12 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, -1) = ? ERESTART_RESTARTBLOCK (To be restarted)
01:10:41 restart_syscall(<... resuming interrupted call ...>) = 1
01:10:41 read(5, "l\4\1\1\v\0\0\0K\2\0\0~\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\f\0\0\0SystemAction\0\0\0\0\10\1g\0\1s\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\6\0\0\0resume\0", 2048) = 155
01:10:42 read(5, 0x2a9d8, 2048) = -1 EAGAIN (Resource temporarily unavailable)
01:10:42 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:42 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, -1) = 1 ([{fd=5, revents=POLLIN}])
01:10:42 read(5, "l\4\1\1\n\0\0\0M\2\0\0~\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\f\0\0\0SystemAction\0\0\0\0\10\1g\0\1s\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\5\0\0\0alive\0l\4\1\1<\0\0\0O\2\0\0\206\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\17\0\0\0ResourceChanged\0\10\1g\0\7sba{sv}\0\0\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\3\0\0\0CPU\0\1\0\0\0,\0\0\0\6\0\0\0policy\0\1i\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0refcount\0\1i\0\1\0\0\0", 2048) = 366
01:10:43 read(5, "l\1\0\1\0\0\0\0P\2\0\0\206\0\0\0\1\1o\0 \0\0\0/org/freesmartphone/Resource/GSM\0\0\0\0\0\0\0\0\6\1s\0\6\0\0\0:1.110\0\0\2\1s\0\33\0\0\0org.freesmartphone.Resource\0\0\0\0\0\3\1s\0\6\0\0\0Resume\0\0\7\1s\0\5\0\0\0:1.87\0\0\0", 2048) = 152
01:10:43 read(5, 0x2a9d8, 2048) = -1 EAGAIN (Resource temporarily unavailable)
01:10:43 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:43 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:43 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:43 gettimeofday({1278537043, 552288}, NULL) = 0
01:10:43 write(25, "2010-07-07T21:10:43.552288Z [DEBUG] DBusServiceResource <GSM>: Resuming resource DBusServiceResource...\n", 104) = 104
01:10:43 gettimeofday({1278537043, 569786}, NULL) = 0
01:10:43 write(25, "2010-07-07T21:10:43.569786Z [DEBUG] DBusServiceResource <GSM>: Resuming GSM resource...\n", 88) = 88
01:10:43 write(1, "** (process:24427): DEBUG: plugin.vala:129: lowlevel_openmoko_resume()\n", 71) = 71
01:10:43 open("/sys/bus/platform/devices/neo1973-pm-gsm.0/flowcontrolled", O_WRONLY) = 36
01:10:43 write(36, "0", 1) = 1
01:10:43 close(36) = 0
01:10:43 gettimeofday({1278537043, 718492}, NULL) = 0
01:10:43 write(15, "2010-07-07T21:10:43.718492Z [DEBUG] FsoGsmGenericWatchDog <P:|KR:true>: onModemStatusChange FSO_GSM_MODEM_STATUS_SUSPENDED -> FSO_GSM_MODEM_STATUS_RESUMING\n", 156) = 156
01:10:43 writev(5, [{"l\4\1\1\r\0\0\0(\0\0\0o\0\0\0\1\1o\0\36\0\0\0/org/freesmartphone/GSM/Device\0\0\2\1s\0\35\0\0\0org.freesmartphone.GSM.Device\0\0\0\3\1s\0\f\0\0\0DeviceStatus\0\0\0\0\10\1g\0\1s\0\0", 128}, {"\10\0\0\0resuming\0", 13}], 2) = 141
01:10:43 gettimeofday({1278537043, 808857}, NULL) = 0
01:10:43 write(8, "2010-07-07T21:10:43.808857Z [INFO] TiCalypsoModem <4C>: Modem Status changed to FSO_GSM_MODEM_STATUS_RESUMING\n", 111) = 111
01:10:43 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 1 ([{fd=29, revents=POLLIN}])
01:10:43 read(29, "~\r\357\r\n+CMT: ,28\r\n5~", 4095) = 18
01:10:43 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:43 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:43 clock_gettime(CLOCK_MONOTONIC, {269040, 68719006}) = 0
01:10:43 clock_gettime(CLOCK_MONOTONIC, {269040, 94766006}) = 0
01:10:43 write(29, "~\17\357AT\357~", 7) = 7
01:10:43 clock_gettime(CLOCK_MONOTONIC, {269040, 105272006}) = 0
01:10:43 clock_gettime(CLOCK_MONOTONIC, {269040, 110155006}) = 0
01:10:43 write(29, "~\17\357+CREG=2\357~", 12) = 12
01:10:43 clock_gettime(CLOCK_MONOTONIC, {269040, 141042006}) = 0
01:10:43 clock_gettime(CLOCK_MONOTONIC, {269040, 145979006}) = 0
01:10:43 write(29, "~\17\357\r\n\357~", 7) = 7
01:10:44 gettimeofday({1278537044, 23222}, NULL) = 0
01:10:44 write(21, "2010-07-07T21:10:44.023222Z [DEBUG] libfsotransport <0710:3>: Wrote '+CREG=2'. Waiting for answer...\n", 101) = 101
01:10:44 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
01:10:44 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, -1) = 1 ([{fd=29, revents=POLLIN}])
01:10:44 read(29, "~\r\357\r\n07919730071111F10414D04937BD2C7797E9D3E614000", 4095) = 50
01:10:44 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, -1) = 1 ([{fd=29, revents=POLLIN}])
01:10:44 read(29, "00170801070556105F4F29C2E03\r\n5~~\r\357\r\nOK\r\n5~", 4046) = 42
01:10:44 gettimeofday({1278537044, 553506}, NULL) = 0
01:10:44 write(21, "2010-07-07T21:10:44.553506Z [INFO] libfsotransport <0710:3>: SRC: \"+CREG=2\" -> [ \"07919730071111F10414D04937BD2C7797E9D3E61400000170801070556105F4F29C2E03\", \"OK\" ]\n", 165) = 165
comment:3 Changed 3 years ago by mickey
I'm not sure the strace is related to this issue, however it pinpoints another interesting bug, namely what happens when the resume commands mix with incoming URCs. Details here in the IRC log:
<mickey|grr> the problem is that all my AT commands know about prefixes etc. <mickey|grr> however <mickey|grr> the bulk commands send @ init and suspend/resume bypass the logic <PaulFertser?> mickey|grr: endoflinePerhapsSolicited should not assume PDU is for it when pendingpdu was set by endoflineSurelyUnsolicited <PaulFertser?> mickey|grr: no? <mickey|grr> no <mickey|grr> the bulk commands are sent without the notion of known prefixes <mickey|grr> and this is the actual problem <mickey|grr> i took a shortcut here <mickey|grr> :/ <mickey|grr> you might be right, btw. <PaulFertser?> mickey|grr: i tried to follow the code logic closely. I can imagine the +CMT: is handled by endoflineSurelyUnsolicited, sets pendingPDU. And then you emit another command. <PaulFertser?> mickey|grr: haveCommand() returns true; <PaulFertser?> so the PDU is handled by PerhapsSolicited?
- mzanetti hat die Verbindung getrennt (Ping timeout: 240 seconds)
<mickey|grr> hmm, right <mickey|grr> so i would need to track who set the 'pendingPDU' <mickey|grr> or rather differenciate <mickey|grr> unsolicitedPendingPDU <mickey|grr> and <mickey|grr> solicitedPendingPDU
Changed 3 years ago by PaulFertser
- Attachment 0001-fsogsmd-distinguish-between-pending-unsolicited-and-.patch added
comment:4 Changed 3 years ago by PaulFertser
Sorry, couldn't resist trying to fix it. And sorry for mixing this two issues into one ticket, hopefully we'll close it soon.
12:08:31 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, -1) = ? ERESTART_RESTARTBLOCK (To be restarted)
12:09:29 restart_syscall(<... resuming interrupted call ...>) = 1
12:09:29 read(5, "l\4\1\1\v\0\0\0\256\2\0\0~\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\f\0\0\0SystemAction\0\0\0\0\10\1g\0\1s\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\6\0\0\0resume\0", 2048) = 155
12:09:29 read(5, 0x2a9d8, 2048) = -1 EAGAIN (Resource temporarily unavailable)
12:09:29 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:29 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, -1) = 1 ([{fd=5, revents=POLLIN}])
12:09:29 read(5, "l\4\1\1\n\0\0\0\260\2\0\0~\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\f\0\0\0SystemAction\0\0\0\0\10\1g\0\1s\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\5\0\0\0alive\0", 2048) = 154
12:09:30 read(5, "l\4\1\1<\0\0\0\262\2\0\0\206\0\0\0\1\1o\0\31\0\0\0/org/freesmartphone/Usage\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.freesmartphone.Usage\0\0\0\0\0\0\0\0\3\1s\0\17\0\0\0ResourceChanged\0\10\1g\0\7sba{sv}\0\0\0\0\7\1s\0\5\0\0\0:1.87\0\0\0\3\0\0\0CPU\0\1\0\0\0,\0\0\0\6\0\0\0policy\0\1i\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0refcount\0\1i\0\1\0\0\0", 2048) = 212
12:09:30 read(5, "l\1\0\1\0\0\0\0\263\2\0\0\206\0\0\0\1\1o\0 \0\0\0/org/freesmartphone/Resource/GSM\0\0\0\0\0\0\0\0\6\1s\0\6\0\0\0:1.113\0\0\2\1s\0\33\0\0\0org.freesmartphone.Resource\0\0\0\0\0\3\1s\0\6\0\0\0Resume\0\0\7\1s\0\5\0\0\0:1.87\0\0\0", 2048) = 152
12:09:30 read(5, 0x2a9d8, 2048) = -1 EAGAIN (Resource temporarily unavailable)
12:09:30 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:30 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:30 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:30 gettimeofday({1278576570, 752872}, NULL) = 0
12:09:30 write(25, "2010-07-08T08:09:30.752872Z [DEBUG] DBusServiceResource <GSM>: Resuming resource DBusServiceResource...\n", 104) = 104
12:09:30 gettimeofday({1278576570, 814910}, NULL) = 0
12:09:30 write(25, "2010-07-08T08:09:30.814910Z [DEBUG] DBusServiceResource <GSM>: Resuming GSM resource...\n", 88) = 88
12:09:30 brk(0x80000) = 0x80000
12:09:30 write(1, "** (process:403): DEBUG: plugin.vala:129: lowlevel_openmoko_resume()\n", 69) = 69
12:09:30 open("/sys/bus/platform/devices/neo1973-pm-gsm.0/flowcontrolled", O_WRONLY) = 36
12:09:30 write(36, "0", 1) = 1
12:09:31 close(36) = 0
12:09:31 gettimeofday({1278576571, 80415}, NULL) = 0
12:09:31 write(15, "2010-07-08T08:09:31.080415Z [DEBUG] FsoGsmGenericWatchDog <P:|KR:true>: onModemStatusChange FSO_GSM_MODEM_STATUS_SUSPENDED -> FSO_GSM_MODEM_STATUS_RESUMING\n", 156) = 156
12:09:31 writev(5, [{"l\4\1\1\r\0\0\0!\0\0\0o\0\0\0\1\1o\0\36\0\0\0/org/freesmartphone/GSM/Device\0\0\2\1s\0\35\0\0\0org.freesmartphone.GSM.Device\0\0\0\3\1s\0\f\0\0\0DeviceStatus\0\0\0\0\10\1g\0\1s\0\0", 128}, {"\10\0\0\0resuming\0", 13}], 2) = 141
12:09:31 gettimeofday({1278576571, 163036}, NULL) = 0
12:09:31 write(8, "2010-07-08T08:09:31.163036Z [INFO] TiCalypsoModem <4C>: Modem Status changed to FSO_GSM_MODEM_STATUS_RESUMING\n", 111) = 111
12:09:31 poll([{fd=6, events=POLLIN}, {fd=29, events=POLLIN}, {fd=5, events=POLLIN}], 3, 0) = 1 ([{fd=29, revents=POLLIN}])
12:09:31 read(29, "~\r\357\r\n+CMT: ,28\r\n5~", 4095) = 18
12:09:31 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:31 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:31 clock_gettime(CLOCK_MONOTONIC, {301735, 124674007}) = 0
12:09:31 clock_gettime(CLOCK_MONOTONIC, {301735, 154214007}) = 0
12:09:31 write(29, "~\17\357AT\357~", 7) = 7
12:09:31 clock_gettime(CLOCK_MONOTONIC, {301735, 182845007}) = 0
12:09:31 clock_gettime(CLOCK_MONOTONIC, {301735, 187827007}) = 0
12:09:31 write(29, "~\17\357+CREG=2\357~", 12) = 12
12:09:31 clock_gettime(CLOCK_MONOTONIC, {301735, 209186007}) = 0
12:09:31 clock_gettime(CLOCK_MONOTONIC, {301735, 233916007}) = 0
12:09:31 write(29, "~\17\357\r\n\357~", 7) = 7
12:09:31 gettimeofday({1278576571, 439122}, NULL) = 0
12:09:31 write(21, "2010-07-08T08:09:31.439122Z [DEBUG] libfsotransport <0710:3>: Wrote '+CREG=2'. Waiting for answer...\n", 101) = 101
12:09:31 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, 0) = 0 (Timeout)
12:09:31 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, -1) = 1 ([{fd=29, revents=POLLIN}])
12:09:31 read(29, "~\r\357\r\n07919730071111F10414D049", 4095) = 29
12:09:31 poll([{fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=29, events=POLLIN}], 3, -1) = 1 ([{fd=29, revents=POLLIN}])
12:09:31 read(29, "37BD2C7797E9D3E61400000170801135306105F4F29C1E03\r\n5~~\r\357\r\nOK\r\n5~", 4067) = 63
12:09:31 gettimeofday({1278576571, 910198}, NULL) = 0
12:09:31 write(21, "2010-07-08T08:09:31.910198Z [INFO] libfsotransport <0710:3>: URC: [ \"+CMT: ,28\", \"07919730071111F10414D04937BD2C7797E9D3E61400000170801135306105F4F29C1E03\" ]\n", 159) = 159
12:09:31 gettimeofday({1278576571, 932672}, NULL) = 0
12:09:31 write(11, "2010-07-08T08:09:31.932672Z [DEBUG] TiCalypsoUnsolicitedResponseHandler : Dispatching AT unsolicited '+CMT', ',28'\n", 115) = 115
12:09:31 gettimeofday({1278576571, 961589}, NULL) = 0
12:09:31 write(8, "2010-07-08T08:09:31.961589Z [DEBUG] TiCalypsoModem <4C>: Did receive a valid response for FsoGsmPlusCMT\n", 104) = 104
12:09:32 gettimeofday({1278576572, 17248}, NULL) = 0
12:09:32 write(21, "2010-07-08T08:09:32.017248Z [INFO] libfsotransport <0710:3>: SRC: \"+CREG=2\" -> [ \"OK\" ]\n", 89) = 89
