remote hang up makes ttyACM0 die

Tue, 2007-06-05 16:26 — aram

Hi, I am using Asterisk 1.4.4 with celliax (did svn update from celliax_stuff a week ago) and a c350. I call from my other cell phone to the c350 and things go well if hang up is originated from my asterisk extension. But when I hang up using the external cell phone, celliax reports an error and then marks ttyACM0 dead.

I have the default celliax.conf

here's the console log. In this test I did 2 exact calls: called from my cell phone to the c350. For the first call I hang up using the asterisk extension and it worked fine. For the second call, I hang up using the external cell phone and ttyACM0 went dead. Any help will be much appreciated.

[Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5146 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5166 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5220 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5233 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5239 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5233 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5239 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:2956 do_monitor: [b7a73bb0][NOTICE [Jun 5 12:48:31] NOTICE[4725]: chan_celliax.c:1441 celliax_indicate: [b7893bb0][NOTICE [Jun 5 12:48:33] NOTICE[4725]: chan_celliax.c:1441 celliax_indicate: [b7893bb0][NOTICE [Jun 5 12:48:33] NOTICE[4725]: chan_celliax.c:1441 celliax_indicate: [b7893bb0][NOTICE [Jun 5 12:48:33] ERROR[4725]: chan_celliax.c:5576 serial_answer_AT: [b7893bb0][ERROR [Jun 5 12:48:34] NOTICE[4725]: chan_celliax.c:1688 celliax_answer: [b7893bb0][NOTICE [Jun 5 12:48:40] NOTICE[4725]: chan_celliax.c:1641 celliax_hangup: [b7893bb0][NOTICE [Jun 5 12:49:11] ERROR[4715]: chan_celliax.c:4997 serial_read_AT: [b7a73bb0][ERROR panba*CLI>
[Jun 5 12:49:42] ERROR[4715]: chan_celliax.c:4997 serial_read_AT: [b7a73bb0][ERROR [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5146 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5166 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5220 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5233 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5239 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5233 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5239 serial_read_AT: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:2956 do_monitor: [b7a73bb0][NOTICE [Jun 5 12:50:12] NOTICE[4955]: chan_celliax.c:1441 celliax_indicate: [b7857bb0][NOTICE [Jun 5 12:50:17] NOTICE[4955]: chan_celliax.c:1441 celliax_indicate: [b7857bb0][NOTICE [Jun 5 12:50:17] NOTICE[4955]: chan_celliax.c:1441 celliax_indicate: [b7857bb0][NOTICE [Jun 5 12:50:17] ERROR[4955]: chan_celliax.c:5576 serial_answer_AT: [b7857bb0][ERROR [Jun 5 12:50:17] NOTICE[4955]: chan_celliax.c:1688 celliax_answer: [b7857bb0][NOTICE [Jun 5 12:50:31] NOTICE[4955]: chan_celliax.c:1641 celliax_hangup: [b7857bb0][NOTICE [Jun 5 12:51:04] ERROR[4715]: chan_celliax.c:4644 serial_getstatus_AT: [b7a73bb0][ERROR [Jun 5 12:51:04] ERROR[4715]: chan_celliax.c:2841 do_monitor: [b7a73bb0][ERROR [Jun 5 12:51:04] ERROR[4715]: chan_celliax.c:2919 do_monitor: [b7a73bb0][ERROR 5146 ][nicephone ][-1, 0,104, 0] phonebook struct: |+CPBR: 1-10,40,24|
5166 ][nicephone ][-1, 0,104, 0] First entry: 1, last entry: 10, phone number max lenght: 40, text max lenght: 24
5220 ][nicephone ][-1, 0,104, 0] phonebook entry: |+CPBR: 1,"+541164422726",145,"Aram"|
5233 ][nicephone ][-1, 0,104, 0] Number: +541164422726, Text: Aram, Type: 145
5239 ][nicephone ][-1, 0,104, 0] incoming callid: Text: Aram, Number: +541164422726[Jun 5 12:48:30] NOTICE[4715]: chan_celliax.c:5220 serial_read_AT: [b7a73bb0][NOTICE 5220 ][nicephone ][-1, 4, 4, 0] phonebook entry: |+CPBR: 2,"+541152469100",145,""|
5233 ][nicephone ][-1, 4, 4, 0] Number: +541152469100, Text: , Type: 145
5239 ][nicephone ][-1, 4, 4, 0] incoming callid: Text: , Number: +541152469100
2956 ][nicephone ][-1, 4, 4, 0] INCOMING RING
1441 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE 3
1441 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE 17
1441 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE -1
5576 ][nicephone ][ 4, 4, 4, 0] at_answer command failed, command used: ATA, trying with AT+CKPD="S"
1688 ][nicephone ][ 4, 6, 6, 0] call answered
1641 ][nicephone ][-1, 0, 0, 0] Hanged Up
4997 ][nicephone ][-1, 0, 0, 0] |+CSQ: 3,99| ALMOST NO SIGNAL
4997 ][nicephone ][-1, 0, 0, 0] |+CSQ: 9,99| ALMOST NO SIGNAL
5146 ][nicephone ][-1, 0,104, 0] phonebook struct: |+CPBR: 1-10,40,24|
5166 ][nicephone ][-1, 0,104, 0] First entry: 1, last entry: 10, phone number max lenght: 40, text max lenght: 24
5220 ][nicephone ][-1, 0,104, 0] phonebook entry: |+CPBR: 1,"+541164422726",145,"Aram"|
5233 ][nicephone ][-1, 0,104, 0] Number: +541164422726, Text: Aram, Type: 145
5239 ][nicephone ][-1, 0,104, 0] incoming callid: Text: Aram, Number: +541164422726[Jun 5 12:50:12] NOTICE[4715]: chan_celliax.c:5220 serial_read_AT: [b7a73bb0][NOTICE 5220 ][nicephone ][-1, 4, 4, 0] phonebook entry: |+CPBR: 2,"+541152469100",145,""|
5233 ][nicephone ][-1, 4, 4, 0] Number: +541152469100, Text: , Type: 145
5239 ][nicephone ][-1, 4, 4, 0] incoming callid: Text: , Number: +541152469100
2956 ][nicephone ][-1, 4, 4, 0] INCOMING RING
1441 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE 3
1441 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE 17
1441 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE -1
5576 ][nicephone ][ 4, 4, 4, 0] at_answer command failed, command used: ATA, trying with AT+CKPD="S"
1688 ][nicephone ][ 4, 6, 6, 0] call answered
1641 ][nicephone ][-1, 0, 0, 0] Hanged Up
4644 ][nicephone ][-1, 0, 0, 0] AT was not acknowledged
2841 ][nicephone ][-1, 0, 0, 0] serial getstatus failed, declaring /dev/ttyACM0 dead
2919 ][none ][-1,-1,-1,-1] select returned -1: Bad file descriptor

chan_celliax on Linux

Add new comment

Tue, 2007-06-05 16:56 — gmaruzz

Ciao Aram, not sure about...

Ciao Aram, not sure about... This happens also if it is the first time that a call comes (I mean, also if you do not try first with hangup generated by asterisk side)?

Also, would you like to do another svn update, make clean, make install, so we're sure we check the same sources?

ciao for now,

Giovanni

Tue, 2007-06-05 17:03 — gmaruzz

Also, can you edit the

Also, can you edit the celliax.conf file to enable debug_at , and from the asterisk CLI, before making the call, enter: "set debug 100" ?

Tue, 2007-06-05 17:09 — gmaruzz

Also, after the bad happens,

Also, after the bad happens, can you do a dmesg from the linux command line?

Maybe is just the the driver that disconnects itself, that was fixed recently...

Tue, 2007-06-05 17:13 — gmaruzz

Mmmmmmh, reading and

Mmmmmmh, reading and rereading your log, I'm almost convinced that the cause is the driver that disconnect itself.
Try svn update, make clean, make install

Please let us know how this proceed

Tue, 2007-06-05 19:22 — aram

The error happens no matter

The error happens no matter if it is the first or second call..

I did svn update, make clean, make and nothing seems to have changed. I am using trunk , is that correct? Also got the asterisk-1.4.4.tar.gz from digium instead of using the source from asterisk svn.

In one ocassion I got this results from dmesg... but in all other tests nothing like this appeared (rebooting in the middle, obviously):

usb 3-1: USB disconnect, address 2
usb 3-1: new full speed USB device using address 3
drivers/usb/class/cdc-acm.c: Ignoring extra header
cdc_acm 3-1:1.0: ttyACM0: USB ACM device

What is the best way to reset the usb port? I always reboot the system (just because I don't know of a faster way)...

this is the console with 'set debug 100' and debug_at=yes

Asterisk Ready.
*CLI> set debug 100
Core debug was 0 and is now 100
The 'set debug' command is deprecated and will be removed in a future release. Please use 'core set debug' instead.
*CLI> [Jun 5 16:19:04] ERROR[4965]: chan_celliax.c:5008 serial_read_AT: [b7a9bbb0][ERROR 5008 ][nicephone ][-1, 0, 0, 0] |+CSQ: 9,99| ALMOST NO SIGNAL
[Jun 5 16:19:35] ERROR[4965]: chan_celliax.c:5008 serial_read_AT: [b7a9bbb0][ERROR 5008 ][nicephone ][-1, 0, 0, 0] |+CSQ: 9,99| ALMOST NO SIGNAL
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5157 serial_read_AT: [b7a9bbb0][NOTICE 5157 ][nicephone ][-1, 0,104, 0] phonebook struct: |+CPBR: 1-10,40,24|
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5177 serial_read_AT: [b7a9bbb0][NOTICE 5177 ][nicephone ][-1, 0,104, 0] First entry: 1, last entry: 10, phone number max lenght: 40, text max lenght: 24
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5231 serial_read_AT: [b7a9bbb0][NOTICE 5231 ][nicephone ][-1, 0,104, 0] phonebook entry: |+CPBR: 1,"+541164422726",145,"Aram"|
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5244 serial_read_AT: [b7a9bbb0][NOTICE 5244 ][nicephone ][-1, 0,104, 0] Number: +541164422726, Text: Aram, Type: 145
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5250 serial_read_AT: [b7a9bbb0][NOTICE 5250 ][nicephone ][-1, 0,104, 0] incoming callid: Text: Aram, Number: +541164422726[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5231 serial_read_AT: [b7a9bbb0][NOTICE 5231 ][nicephone ][-1, 4, 4, 0] phonebook entry: |+CPBR: 2,"+541152469100",145,""|
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5244 serial_read_AT: [b7a9bbb0][NOTICE 5244 ][nicephone ][-1, 4, 4, 0] Number: +541152469100, Text: , Type: 145
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:5250 serial_read_AT: [b7a9bbb0][NOTICE 5250 ][nicephone ][-1, 4, 4, 0] incoming callid: Text: , Number: +541152469100
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:2967 do_monitor: [b7a9bbb0][NOTICE 2967 ][nicephone ][-1, 4, 4, 0] INCOMING RING
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:1958 celliax_new: [b7a9bbb0][NOTICE 1958 ][nicephone ][-1, 4, 4, 0] ENTERING FUNC
[Jun 5 16:20:01] NOTICE[4965]: chan_celliax.c:2058 celliax_new: [b7a9bbb0][NOTICE 2058 ][nicephone ][ 4, 4, 4, 0] EXITING FUNC
[Jun 5 16:20:02] NOTICE[5014]: chan_celliax.c:1460 celliax_indicate: [b78bbbb0][NOTICE 1460 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE 3
[Jun 5 16:20:03] NOTICE[5014]: chan_celliax.c:1460 celliax_indicate: [b78bbbb0][NOTICE 1460 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE 17
[Jun 5 16:20:03] NOTICE[5014]: chan_celliax.c:1460 celliax_indicate: [b78bbbb0][NOTICE 1460 ][nicephone ][ 4, 4, 4, 0] Let's INDICATE -1
[Jun 5 16:20:03] NOTICE[5014]: chan_celliax.c:1684 celliax_answer: [b78bbbb0][NOTICE 1684 ][nicephone ][ 4, 4, 4, 0] ENTERING FUNC
[Jun 5 16:20:03] ERROR[5014]: chan_celliax.c:5587 serial_answer_AT: [b78bbbb0][ERROR 5587 ][nicephone ][ 4, 4, 4, 0] at_answer command failed, command used: ATA, trying with AT+CKPD="S"
[Jun 5 16:20:03] NOTICE[5014]: chan_celliax.c:1707 celliax_answer: [b78bbbb0][NOTICE 1707 ][nicephone ][ 4, 6, 6, 0] call answered
[Jun 5 16:20:03] NOTICE[5014]: chan_celliax.c:1711 celliax_answer: [b78bbbb0][NOTICE 1711 ][nicephone ][ 4, 6, 6, 0] EXITING FUNC
[Jun 5 16:20:06] ERROR[5015]: chan_celliax.c:5008 serial_read_AT: [b787fbb0][ERROR 5008 ][nicephone ][ 6, 6, 6, 0] |+CSQ: 9,99| ALMOST NO SIGNAL
[Jun 5 16:20:11] NOTICE[5014]: chan_celliax.c:1557 celliax_hangup: [b78bbbb0][NOTICE 1557 ][nicephone ][ 6, 6, 0, 0] ENTERING FUNC
Really destroying SIP dialog '7acd54542dbf1af01619e4b730c02ad2@190.55.117.94' Method: INVITE
[Jun 5 16:20:11] NOTICE[5014]: chan_celliax.c:1660 celliax_hangup: [b78bbbb0][NOTICE 1660 ][nicephone ][-1, 0, 0, 0] Hanged Up
[Jun 5 16:20:11] NOTICE[5014]: chan_celliax.c:1671 celliax_hangup: [b78bbbb0][NOTICE 1671 ][nicephone ][-1, 0, 0, 0] EXITING FUNC
[Jun 5 16:20:44] ERROR[4965]: chan_celliax.c:4655 serial_getstatus_AT: [b7a9bbb0][ERROR 4655 ][nicephone ][-1, 0, 0, 0] AT was not acknowledged
[Jun 5 16:20:44] ERROR[4965]: chan_celliax.c:2852 do_monitor: [b7a9bbb0][ERROR 2852 ][nicephone ][-1, 0, 0, 0] serial getstatus failed, declaring /dev/ttyACM0 dead
[Jun 5 16:20:44] ERROR[4965]: chan_celliax.c:2930 do_monitor: [b7a9bbb0][ERROR 2930 ][none ][-1,-1,-1,-1] select returned -1: Bad file descriptor

Wed, 2007-06-06 08:52 — gmaruzz

the dmesg log says something

the dmesg log says something about an USB disconnect...

I'll do some test today, I have a c350 with which to test in your same conditions.

I'll write you more here when I've done the tests.

In the mean time, thank you a lot for your testing and reporting!!!!

Wed, 2007-06-06 09:45 — gmaruzz

Ciao Aram, you have to edit

Ciao Aram, you have to edit the logger.conf file, so that the debug messages are printed on the console, or you cannot see debug messages.

I've done a couple of tests, exactly in your conditions: latest sources, motorola c350 on USB.

I've called into the 350 from my cell, listen some second of welcome message, then hangup my cell, and I've not got problems.

Can you repeat the tests with debug messages in console (editing logger.conf) ?

They will give results like this (for no problem) :

Asterisk Ready.
*CLI> set debug 100
Core debug was 0 and is now 100
The 'set debug' command is deprecated and will be removed in a future release. Please use 'core set debug' instead.
*CLI> [Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:2838 do_monitor: [b785cba0][DEBUG_SERIAL 2838 ][nicephone ][-1, 0, 0, 0] Syncing Serial
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5519 serial_write_AT_ack: [b785cba0][DEBUG_AT 5519 ][nicephone ][-1, 0, 0, 0] sending: AT
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (A)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (T)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0, 0, 0] Read line 0: |OK|
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5371 serial_read_AT: [b785cba0][DEBUG_AT 5371 ][nicephone ][-1, 0, 0, 0] got OK
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5542 serial_write_AT_expect: [b785cba0][DEBUG_AT 5542 ][nicephone ][-1, 0, 0, 0] sending: AT+CBC, expecting: OK
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (A)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (T)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (+)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (C)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (B)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (C)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0, 0, 0] Read line 0: |+CBC: 0,60|
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0, 0, 0] Read line 1: |OK|
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:4979 serial_read_AT: [b785cba0][DEBUG_AT 4979 ][nicephone ][-1, 0, 0, 0] |+CBC: 0,60| +CBC: Powered by battery, battery strenght=60
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5365 serial_read_AT: [b785cba0][DEBUG_AT 5365 ][nicephone ][-1, 0, 0, 0] |OK| got what EXPECTED
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5542 serial_write_AT_expect: [b785cba0][DEBUG_AT 5542 ][nicephone ][-1, 0, 0, 0] sending: AT+CSQ, expecting: OK
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (A)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (T)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (+)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (C)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (S)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0, 0, 0] sending data... (Q)
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0, 0, 0] Read line 0: |+CSQ: 21,99|
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0, 0, 0] Read line 1: |OK|
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5001 serial_read_AT: [b785cba0][DEBUG_AT 5001 ][nicephone ][-1, 0, 0, 0] |+CSQ: 21,99| +CSQ: Signal Quality: 21, Error Rate=99
[Jun 6 11:22:31] DEBUG[18914]: chan_celliax.c:5365 serial_read_AT: [b785cba0][DEBUG_AT 5365 ][nicephone ][-1, 0, 0, 0] |OK| got what EXPECTED

*CLI> [Jun 6 11:22:47] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0, 0, 0] Read line 0: |+MCST: 17|
[Jun 6 11:22:47] DEBUG[18914]: chan_celliax.c:5120 serial_read_AT: [b785cba0][DEBUG_AT 5120 ][nicephone ][-1, 0,103, 0] |+MCST: 17| CALLFLOW_CALL_INFLUX
[Jun 6 11:22:47] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0,103, 0] Read line 1: |+MCST: 2|
[Jun 6 11:22:47] DEBUG[18914]: chan_celliax.c:5035 serial_read_AT: [b785cba0][DEBUG_AT 5035 ][nicephone ][-1, 0,103, 0] |+MCST: 2| CALLFLOW_CALL_INCOMING
[Jun 6 11:22:48] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0,104, 0] Read line 0: |+MCST: 2|
[Jun 6 11:22:48] DEBUG[18914]: chan_celliax.c:5035 serial_read_AT: [b785cba0][DEBUG_AT 5035 ][nicephone ][-1, 0,104, 0] |+MCST: 2| CALLFLOW_CALL_INCOMING
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5519 serial_write_AT_ack: [b785cba0][DEBUG_AT 5519 ][nicephone ][-1, 0,104, 0] sending: AT+CPBS=RC
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (A)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (T)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (+)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (C)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (P)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (B)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (S)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (=)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (R)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (C)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0,104, 0] Read line 0: |OK|
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5371 serial_read_AT: [b785cba0][DEBUG_AT 5371 ][nicephone ][-1, 0,104, 0] got OK
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5519 serial_write_AT_ack: [b785cba0][DEBUG_AT 5519 ][nicephone ][-1, 0,104, 0] sending: AT+CPBR=?
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (A)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (T)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (+)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (C)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (P)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (B)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (R)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (=)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (?)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0,104, 0] Read line 0: |+CPBR: 1-10,40,24|
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0,104, 0] Read line 1: |OK|
[Jun 6 11:22:50] NOTICE[18914]: chan_celliax.c:5156 serial_read_AT: [b785cba0][NOTICE 5156 ][nicephone ][-1, 0,104, 0] phonebook struct: |+CPBR: 1-10,40,24|
[Jun 6 11:22:50] NOTICE[18914]: chan_celliax.c:5176 serial_read_AT: [b785cba0][NOTICE 5176 ][nicephone ][-1, 0,104, 0] First entry: 1, last entry: 10, phone number max lenght: 40, text max lenght: 24
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5371 serial_read_AT: [b785cba0][DEBUG_AT 5371 ][nicephone ][-1, 0,104, 0] got OK
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5564 serial_write_AT_expect_longtime: [b785cba0][DEBUG_AT 5564 ][nicephone ][-1, 0,104, 0] sending: AT+CPBR=1,10, expecting: OK
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (A)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (T)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (+)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (C)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (P)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (B)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (R)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (=)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (1)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (,)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (1)
[Jun 6 11:22:50] DEBUG[18914]: chan_celliax.c:5481 serial_write_AT: [b785cba0][DEBUG_AT 5481 ][nicephone ][-1, 0,104, 0] sending data... (0)
[Jun 6 11:22:51] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 0,104, 0] Read line 0: |+CPBR: 1,"+393472665618",145,""|
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:5230 serial_read_AT: [b785cba0][NOTICE 5230 ][nicephone ][-1, 0,104, 0] phonebook entry: |+CPBR: 1,"+393472665618",145,""|
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:5243 serial_read_AT: [b785cba0][NOTICE 5243 ][nicephone ][-1, 0,104, 0] Number: +393472665618, Text: , Type: 145
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:5249 serial_read_AT: [b785cba0][NOTICE 5249 ][nicephone ][-1, 0,104, 0] incoming callid: Text: , Number: +393472665618
[Jun 6 11:22:51] DEBUG[18914]: chan_celliax.c:5254 serial_read_AT: [b785cba0][DEBUG_AT 5254 ][nicephone ][-1, 0,104, 0] |+CPBR: 1,"+393472665618",145,""| CPBR INCOMING CALLID: name is , number is +393472665618
[Jun 6 11:22:51] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 4, 4, 0] Read line 1: |+CPBR: 2,"+393472665618",145,""|
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:5230 serial_read_AT: [b785cba0][NOTICE 5230 ][nicephone ][-1, 4, 4, 0] phonebook entry: |+CPBR: 2,"+393472665618",145,""|
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:5243 serial_read_AT: [b785cba0][NOTICE 5243 ][nicephone ][-1, 4, 4, 0] Number: +393472665618, Text: , Type: 145
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:5249 serial_read_AT: [b785cba0][NOTICE 5249 ][nicephone ][-1, 4, 4, 0] incoming callid: Text: , Number: +393472665618
[Jun 6 11:22:51] DEBUG[18914]: chan_celliax.c:5254 serial_read_AT: [b785cba0][DEBUG_AT 5254 ][nicephone ][-1, 4, 4, 0] |+CPBR: 2,"+393472665618",145,""| CPBR INCOMING CALLID: name is , number is +393472665618
[Jun 6 11:22:51] DEBUG[18914]: chan_celliax.c:4814 serial_read_AT: [b785cba0][DEBUG_AT 4814 ][nicephone ][-1, 4, 4, 0] Read line 2: |OK|
[Jun 6 11:22:51] DEBUG[18914]: chan_celliax.c:5365 serial_read_AT: [b785cba0][DEBUG_AT 5365 ][nicephone ][-1, 4, 4, 0] |OK| got what EXPECTED
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:2966 do_monitor: [b785cba0][NOTICE 2966 ][nicephone ][-1, 4, 4, 0] INCOMING RING
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:1956 celliax_new: [b785cba0][NOTICE 1956 ][nicephone ][-1, 4, 4, 0] ENTERING FUNC
[Jun 6 11:22:51] NOTICE[18914]: chan_celliax.c:2056 celliax_new: [b785cba0][NOTICE 2056 ][nicephone ][ 4, 4, 4, 0] EXITING FUNC
[Jun 6 11:22:51] DEBUG[18954]: pbx.c:1809 pbx_extension_helper: Launching 'Wait'
[Jun 6 11:22:52] DEBUG[18954]: pbx.c:1809 pbx_extension_helper: Launching 'Answer'
[Jun 6 11:22:52] NOTICE[18954]: chan_celliax.c:1684 celliax_answer: [b6c83ba0][NOTICE 1684 ][nicephone ][ 4, 4, 4, 0] ENTERING FUNC
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5542 serial_write_AT_expect: [b6c83ba0][DEBUG_AT 5542 ][nicephone ][ 4, 4, 4, 0] sending: ATA, expecting: OK
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (A)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (T)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (A)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:4814 serial_read_AT: [b6c83ba0][DEBUG_AT 4814 ][nicephone ][ 4, 4, 4, 0] Read line 0: |ERROR|
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5377 serial_read_AT: [b6c83ba0][DEBUG_AT 5377 ][nicephone ][ 4, 4, 4, 0] got ERROR
[Jun 6 11:22:52] ERROR[18954]: chan_celliax.c:5586 serial_answer_AT: [b6c83ba0][ERROR 5586 ][nicephone ][ 4, 4, 4, 0] at_answer command failed, command used: ATA, trying with AT+CKPD="S"
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5519 serial_write_AT_ack: [b6c83ba0][DEBUG_AT 5519 ][nicephone ][ 4, 4, 4, 0] sending: AT+CKPD="S"
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (A)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (T)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (+)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (C)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (K)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (P)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (D)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (=)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (")
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (S)
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 4, 4, 4, 0] sending data... (")
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:4814 serial_read_AT: [b6c83ba0][DEBUG_AT 4814 ][nicephone ][ 4, 4, 4, 0] Read line 0: |OK|
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5371 serial_read_AT: [b6c83ba0][DEBUG_AT 5371 ][nicephone ][ 4, 4, 4, 0] got OK
[Jun 6 11:22:52] DEBUG[18954]: chan_celliax.c:5597 serial_answer_AT: [b6c83ba0][DEBUG_AT 5597 ][nicephone ][ 4, 6, 6, 0] AT: call answered
[Jun 6 11:22:52] NOTICE[18954]: chan_celliax.c:1707 celliax_answer: [b6c83ba0][NOTICE 1707 ][nicephone ][ 4, 6, 6, 0] call answered
[Jun 6 11:22:52] NOTICE[18954]: chan_celliax.c:1711 celliax_answer: [b6c83ba0][NOTICE 1711 ][nicephone ][ 4, 6, 6, 0] EXITING FUNC
[Jun 6 11:22:52] DEBUG[18954]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/nicephone
[Jun 6 11:22:52] DEBUG[18954]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
[Jun 6 11:22:52] DEBUG[18954]: pbx.c:1809 pbx_extension_helper: Launching 'Set'
[Jun 6 11:22:52] DEBUG[18954]: pbx.c:1809 pbx_extension_helper: Launching 'BackGround'
[Jun 6 11:22:52] DEBUG[18954]: channel.c:2911 set_format: Set channel Celliax/nicephone to write format gsm
[Jun 6 11:22:52] NOTICE[18954]: chan_celliax.c:3849 alsa_write: [b6c83ba0][NOTICE 3849 ][nicephone ][ 6, 6, 6, 0] reset audio play
[Jun 6 11:22:52] DEBUG[18954]: channel.c:2030 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun 6 11:22:52] DEBUG[18908]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - nicephone
[Jun 6 11:22:52] DEBUG[18908]: devicestate.c:287 do_state_change: Changing state for Celliax/nicephone - state 2 (In use)
[Jun 6 11:22:52] DEBUG[18956]: app_queue.c:546 changethread: Device 'Celliax/nicephone' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 6 11:22:52] DEBUG[18955]: chan_celliax.c:4814 serial_read_AT: [b6c47ba0][DEBUG_AT 4814 ][nicephone ][ 6, 6, 6, 0] Read line 0: |+MCST: 17|
[Jun 6 11:22:52] DEBUG[18955]: chan_celliax.c:5120 serial_read_AT: [b6c47ba0][DEBUG_AT 5120 ][nicephone ][ 6, 6,103, 0] |+MCST: 17| CALLFLOW_CALL_INFLUX
[Jun 6 11:22:53] DEBUG[18955]: chan_celliax.c:4814 serial_read_AT: [b6c47ba0][DEBUG_AT 4814 ][nicephone ][ 6, 6,103, 0] Read line 0: |+MCST: 3|
[Jun 6 11:22:53] DEBUG[18955]: chan_celliax.c:5076 serial_read_AT: [b6c47ba0][DEBUG_AT 5076 ][nicephone ][ 6, 6, 6, 0] |+MCST: 3| CALLFLOW_CALL_ACTIVE

*CLI>
*CLI>
*CLI>
*CLI> [Jun 6 11:22:59] DEBUG[18955]: chan_celliax.c:4814 serial_read_AT: [b6c47ba0][DEBUG_AT 4814 ][nicephone ][ 6, 6, 6, 0] Read line 0: |+MCST: 17|
[Jun 6 11:22:59] DEBUG[18955]: chan_celliax.c:5120 serial_read_AT: [b6c47ba0][DEBUG_AT 5120 ][nicephone ][ 6, 6,103, 0] |+MCST: 17| CALLFLOW_CALL_INFLUX
[Jun 6 11:23:00] DEBUG[18955]: chan_celliax.c:4814 serial_read_AT: [b6c47ba0][DEBUG_AT 4814 ][nicephone ][ 6, 6,103, 0] Read line 0: |+MCST: 1|
[Jun 6 11:23:00] DEBUG[18955]: chan_celliax.c:5022 serial_read_AT: [b6c47ba0][DEBUG_AT 5022 ][nicephone ][ 6, 6, 0, 0] |+MCST: 1| CALLFLOW_CALL_IDLE
[Jun 6 11:23:00] DEBUG[18955]: chan_celliax.c:5024 serial_read_AT: [b6c47ba0][DEBUG_AT 5024 ][nicephone ][ 6, 6, 0, 0] just received a remote HANGUP
[Jun 6 11:23:00] DEBUG[18954]: channel.c:2030 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun 6 11:23:00] DEBUG[18954]: channel.c:2911 set_format: Set channel Celliax/nicephone to write format slin
[Jun 6 11:23:00] DEBUG[18954]: pbx.c:2407 __ast_pbx_run: Spawn extension (default,s,5) exited non-zero on 'Celliax/nicephone'
[Jun 6 11:23:00] DEBUG[18954]: channel.c:1726 ast_hangup: Hanging up channel 'Celliax/nicephone'
[Jun 6 11:23:00] NOTICE[18954]: chan_celliax.c:1557 celliax_hangup: [b6c83ba0][NOTICE 1557 ][nicephone ][ 6, 6, 0, 0] ENTERING FUNC
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5542 serial_write_AT_expect: [b6c83ba0][DEBUG_AT 5542 ][nicephone ][ 6, 6, 0, 0] sending: AT+CKPD="EEE", expecting: OK
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (A)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (T)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (+)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (C)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (K)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (P)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (D)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (=)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (")
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (E)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (E)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (E)
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5481 serial_write_AT: [b6c83ba0][DEBUG_AT 5481 ][nicephone ][ 6, 6, 0, 0] sending data... (")
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:4814 serial_read_AT: [b6c83ba0][DEBUG_AT 4814 ][nicephone ][ 6, 6, 0, 0] Read line 0: |OK|
[Jun 6 11:23:00] DEBUG[18954]: chan_celliax.c:5365 serial_read_AT: [b6c83ba0][DEBUG_AT 5365 ][nicephone ][ 6, 6, 0, 0] |OK| got what EXPECTED
[Jun 6 11:23:00] DEBUG[18954]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/nicephone
[Jun 6 11:23:00] NOTICE[18954]: chan_celliax.c:1660 celliax_hangup: [b6c83ba0][NOTICE 1660 ][nicephone ][-1, 0, 0, 0] Hanged Up
[Jun 6 11:23:00] NOTICE[18954]: chan_celliax.c:1671 celliax_hangup: [b6c83ba0][NOTICE 1671 ][nicephone ][-1, 0, 0, 0] EXITING FUNC
[Jun 6 11:23:00] DEBUG[18954]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/nicephone
[Jun 6 11:23:00] DEBUG[18908]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - nicephone
[Jun 6 11:23:00] DEBUG[18908]: devicestate.c:287 do_state_change: Changing state for Celliax/nicephone - state 1 (Not in use)
[Jun 6 11:23:00] DEBUG[18908]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - nicephone
[Jun 6 11:23:00] DEBUG[18908]: devicestate.c:287 do_state_change: Changing state for Celliax/nicephone - state 1 (Not in use)
[Jun 6 11:23:00] DEBUG[18961]: app_queue.c:546 changethread: Device 'Celliax/nicephone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 6 11:23:00] DEBUG[18962]: app_queue.c:546 changethread: Device 'Celliax/nicephone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.

*CLI>
*CLI>
*CLI> set debug 0
Core debug is now OFF
*CLI> stop now

Wed, 2007-06-06 09:52 — gmaruzz

Also, I see that one

Also, I see that one difference is the SIP interaction...
Can you repeat the tests after modifying the modules.conf file, inserting a

noload => chan_sip.so

in it?

If without SIP works, then we can pinpoint the cause of problems...

Let's indagate

Wed, 2007-06-06 09:56 — gmaruzz

sorry for the stupid

sorry for the stupid question, but you made a "make install" after make clean, or just make? You need "make install" for the new sources to really be in "action".

It definitely seems to happen a driver disconnection (bad file descriptor)

Wed, 2007-06-06 19:06 — aram

still testing... this is all

still testing... this is all I have tried this time
1. made sure I did make clean, make menuselect, make, make install
2. tried with noload=>sip ...
3. enabled debug on console

still same bad thing happens. The one thing I noticed is that your log says 'chan_celliax.c:5481 serial_write_AT...' where mines says 'chan_celliax.c:5482 serial_write_AT: ' (the source code line is different) so I was wondering if I have the wrong sources or you made a local change to your chan_celliax.c

dmesg does not report anything about the usb geting disconnected.

Tomorrow I will try the LiveCD again. I tried it a week ago and I thinked it worked perfectly well. This is to ensure everything is fine with the cellphone.

My console logs look the same as yours. The only difference is that 30 seconds after the hang up, the AT fails. So I have some more lines at the end. The other thing to mention is that I don't need to restart the machine but just asterisk.

I have just found something interesting. The ttyACM0 is marked dead 30 seconds after the hang up. BUT if I call it back before the 30 seconds, it keeps working fine. That 'Syncing Serial' (every 30 secs?) is failing and marking the device dead when it is actually working. Is that possible?

here's the log with debug enabled and no sip

[Jun 6 14:48:07] DEBUG[12771]: chan_celliax.c:4815 serial_read_AT: [b77abbb0][DEBUG_AT 4815 ][nicephone ][ 7, 4, 4, 0] Read line 0: |+MCST: 17|
[Jun 6 14:48:07] DEBUG[12771]: chan_celliax.c:5121 serial_read_AT: [b77abbb0][DEBUG_AT 5121 ][nicephone ][ 7, 4,103, 0] |+MCST: 17| CALLFLOW_CALL_INFLUX
[Jun 6 14:48:08] DEBUG[12771]: chan_celliax.c:4815 serial_read_AT: [b77abbb0][DEBUG_AT 4815 ][nicephone ][ 7, 4,103, 0] Read line 0: |+MCST: 1|
[Jun 6 14:48:08] DEBUG[12771]: chan_celliax.c:5023 serial_read_AT: [b77abbb0][DEBUG_AT 5023 ][nicephone ][ 7, 4, 0, 0] |+MCST: 1| CALLFLOW_CALL_IDLE
[Jun 6 14:48:08] DEBUG[12771]: chan_celliax.c:5025 serial_read_AT: [b77abbb0][DEBUG_AT 5025 ][nicephone ][ 7, 4, 0, 0] just received a remote HANGUP
[Jun 6 14:48:08] DEBUG[12770]: channel.c:1726 ast_hangup: Hanging up channel 'Celliax/nicephone'
[Jun 6 14:48:08] NOTICE[12770]: chan_celliax.c:1557 celliax_hangup: [b77e7bb0][NOTICE 1557 ][nicephone ][ 7, 4, 0, 0] ENTERING FUNC
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5543 serial_write_AT_expect: [b77e7bb0][DEBUG_AT 5543 ][nicephone ][ 7, 4, 0, 0] sending: AT+CKPD="EEE", expecting: OK
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (A)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (T)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (+)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (C)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (K)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (P)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (D)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (=)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (")
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (E)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (E)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (E)
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5482 serial_write_AT: [b77e7bb0][DEBUG_AT 5482 ][nicephone ][ 7, 4, 0, 0] sending data... (")
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:4815 serial_read_AT: [b77e7bb0][DEBUG_AT 4815 ][nicephone ][ 7, 4, 0, 0] Read line 0: |OK|
[Jun 6 14:48:08] DEBUG[12770]: chan_celliax.c:5366 serial_read_AT: [b77e7bb0][DEBUG_AT 5366 ][nicephone ][ 7, 4, 0, 0] |OK| got what EXPECTED
[Jun 6 14:48:08] DEBUG[12771]: chan_celliax.c:1401 unlocka_log: [b77abbb0] I'm a dying thread, and I'm unlocking mutex 0xb7c21ea8
[Jun 6 14:48:08] DEBUG[12770]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/nicephone
[Jun 6 14:48:08] NOTICE[12770]: chan_celliax.c:1660 celliax_hangup: [b77e7bb0][NOTICE 1660 ][nicephone ][-1, 0, 0, 0] Hanged Up
[Jun 6 14:48:08] NOTICE[12770]: chan_celliax.c:1671 celliax_hangup: [b77e7bb0][NOTICE 1671 ][nicephone ][-1, 0, 0, 0] EXITING FUNC
[Jun 6 14:48:08] DEBUG[12770]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Celliax/nicephone
[Jun 6 14:48:08] DEBUG[12745]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - nicephone
[Jun 6 14:48:08] DEBUG[12745]: devicestate.c:287 do_state_change: Changing state for Celliax/nicephone - state 1 (Not in use)
[Jun 6 14:48:08] DEBUG[12745]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Celliax - nicephone
[Jun 6 14:48:08] DEBUG[12745]: devicestate.c:287 do_state_change: Changing state for Celliax/nicephone - state 1 (Not in use)
[Jun 6 14:48:08] DEBUG[12773]: app_queue.c:546 changethread: Device 'Celliax/nicephone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 6 14:48:08] DEBUG[12774]: app_queue.c:546 changethread: Device 'Celliax/nicephone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 6 14:48:39] DEBUG[12762]: chan_celliax.c:2839 do_monitor: [b79c7bb0][DEBUG_SERIAL 2839 ][nicephone ][-1, 0, 0, 0] Syncing Serial
[Jun 6 14:48:39] DEBUG[12762]: chan_celliax.c:5520 serial_write_AT_ack: [b79c7bb0][DEBUG_AT 5520 ][nicephone ][-1, 0, 0, 0] sending: AT
[Jun 6 14:48:39] DEBUG[12762]: chan_celliax.c:5482 serial_write_AT: [b79c7bb0][DEBUG_AT 5482 ][nicephone ][-1, 0, 0, 0] sending data... (A)
[Jun 6 14:48:39] DEBUG[12762]: chan_celliax.c:5482 serial_write_AT: [b79c7bb0][DEBUG_AT 5482 ][nicephone ][-1, 0, 0, 0] sending data... (T)
[Jun 6 14:48:41] ERROR[12762]: chan_celliax.c:4655 serial_getstatus_AT: [b79c7bb0][ERROR 4655 ][nicephone ][-1, 0, 0, 0] AT was not acknowledged
[Jun 6 14:48:41] ERROR[12762]: chan_celliax.c:2852 do_monitor: [b79c7bb0][ERROR 2852 ][nicephone ][-1, 0, 0, 0] serial getstatus failed, declaring /dev/ttyACM0 dead
[Jun 6 14:48:41] ERROR[12762]: chan_celliax.c:2930 do_monitor: [b79c7bb0][ERROR 2930 ][none ][-1,-1,-1,-1] select returned -1: Bad file descriptor

Wed, 2007-06-06 19:14 — gmaruzz

thanks a lot for being so a

thanks a lot for being so a good tester!
It is normal that you have different line numbers, I'm keeping working on the file... :)
Yes, the syncing serial is each 30 secs
Let me study a little while on your post, I'll write more in some ten minutes

Wed, 2007-06-06 19:23 — gmaruzz

btw, if you want to have

btw, if you want to have quick tests on the phone, just use minicom, 38400 8 N 1
still studying...

Wed, 2007-06-06 19:37 — aram

Just tried commenting out

Just tried commenting out the code that marks the ttyACM0 dead and things seem to be working fine.

added replaced

rt = serial_getstatus(p);
if (rt) {

with:

rt = serial_getstatus(p);
if (/* aram */0 && rt) {

in do_monitor.

Any ideas? I am running out of them, :)
I guess my change can lead to unexpected weird behavior, right?

Wed, 2007-06-06 19:56 — gmaruzz

I've done a very similar

I've done a very similar thing for you to test in the sources now in svn, you can svn revert chan_celliax.c then svn update

this will give us more hints, especially if it is able to continue working

anyway, it is not good that in 2.5 secs it do not acknowledge AT... I'm willing to go in deep about this.

btw, thank you for getting my attention on this, because it was selecting on a closed filedescriptor (that is why it reported bad filedescriptor, not because it was the driver to disconnect).

Wed, 2007-06-06 21:16 — aram

Thank YOU for all your help.

Thank YOU for all your help. Yes, now it's working fine. I see the first AT is not acknowledged but chan_celliax keeps going ok.
I will let you know if I see anything weird related (or not related at all).
Ciao, aram

Here's my current logs (nobody is dying now, haha)

[Jun 6 18:09:43] DEBUG[21386]: chan_celliax.c:2870 do_monitor: [b79edbb0][DEBUG_SERIAL 2870 ][nicephone ][-1, 0, 0, 0] Syncing Serial
[Jun 6 18:09:43] DEBUG[21386]: chan_celliax.c:5553 serial_write_AT_ack: [b79edbb0][DEBUG_AT 5553 ][nicephone ][-1, 0, 0, 0] sending: AT
[Jun 6 18:09:43] DEBUG[21386]: chan_celliax.c:5515 serial_write_AT: [b79edbb0][DEBUG_AT 5515 ][nicephone ][-1, 0, 0, 0] sending data... (A)
[Jun 6 18:09:43] DEBUG[21386]: chan_celliax.c:5515 serial_write_AT: [b79edbb0][DEBUG_AT 5515 ][nicephone ][-1, 0, 0, 0] sending data... (T)
[Jun 6 18:09:45] ERROR[21386]: chan_celliax.c:4688 serial_getstatus_AT: [b79edbb0][ERROR 4688 ][nicephone ][-1, 0, 0, 0] AT was not acknowledged
[Jun 6 18:09:45] DEBUG[21386]: chan_celliax.c:5576 serial_write_AT_expect: [b79edbb0][DEBUG_AT 5576 ][nicephone ][-1, 0, 0, 0] sending: AT+CBC, expecting: OK

Wed, 2007-06-06 21:20 — gmaruzz

Celliax.Org

User login

Comments

from SlashDot