search

RoEdAl / asterisk-chan-quectel

Asterisk channel driver for Quectel and SimCOM modules
GNU General Public License v2.0
18 stars 6 forks source link

Asterisk crashes after running for a period of time #25

Open hexuanyi opened 2 weeks ago

hexuanyi commented 2 weeks ago

Asterisk crashes after running for a period of time

Excessive refcount 100000 reached on ao2 object 0x563b7888d528

RoEdAl commented 2 weeks ago

Could you tell me more? Is two-month period enough? What version of Asterisk and chan_quectel you're using? What platform does your Asterisk service run on?

hexuanyi commented 2 weeks ago

Ubuntu22.01 asterisk18.10.1 Compile the latest code used , used is i5,16GB memory ,In 30 concurrent situations, FRACK may occur irregularly!, Failed assertion Excessive refcount 100000 reached on ao2 object
Then I modified the Asterisk source code

file main/astobj2. c

EXCESSIVE_REF_COUNT 900000

File include/ostrisk/taskprocessor. h

AST-TASKPROCESSOR-HIGHT-WATER-LEVEL 20000 still reports FRACK error!, Failed assertion Excessive refcount 900000 reached on ao2 object

RoEdAl commented 2 weeks ago

You have two options:

  1. Build chan_quectel from experimental ao2 branch.
  2. Set refdebug = yes in /etc/asterisk/asterisk.conf, restart service and investigate /var/log/asterisk/refs file.
hexuanyi commented 1 week ago

Connected to Asterisk 18.10.0 currently running on asbt (pid = 11502) -- [quectel0] Opening data port: /dev/ttyUSB2 -- [quectel0] Opening audio port: /dev/ttyUSB1 -- [quectel0] Ports opened, initializing... core dump

hexuanyi commented 1 week ago

use Build chan_quectel from experimental ao2 branch. core dump

RoEdAl commented 1 week ago
hexuanyi commented 1 week ago

Can you give me a contact information?

hexuanyi commented 1 week ago

Asterisk Ready. CLI> core set debug 4 Core debug was OFF and is now 4. CLI> core set verbose 3 Console verbose was 8 and is now 3. CLI> quectel start quectel0 [quectel0] Start scheduled CLI> -- [quectel0] Opening data port: /dev/ttyUSB2 -- [quectel0] Opening audio port: /dev/ttyUSB1 -- [quectel0] Ports opened, initializing... Segmentation fault (core dumped)

RoEdAl commented 1 week ago

You have to configure Asterisk to dump debug messages to console or check out log file for debug messages.

hexuanyi commented 1 week ago

Can you wait for me for a few minutes?

hexuanyi commented 1 week ago

0 0x0000555d52c2f28a in ao2_unlock (user_data=0x7fcca4b5a7b2, file=0x7fcb534e5168 "src/chan_quectel.c", func=0x7fcb534e5db0 <__PRETTY_FUNCTION.68> "pvt_taskproc_lock_and_execute", line=686, var=0x7fcb534e553e "ptd->pvt") at astobj2.c:290

1 0x00007fcb534ce939 in __ao2_unlock_and_unref () from /usr/lib/asterisk/modules/chan_quectel.so

2 0x00007fcb534bee73 in pvt_taskproc_lock_and_execute () from /usr/lib/asterisk/modules/chan_quectel.so

3 0x00007fcb534ba6b0 in at_response_taskproc () from /usr/lib/asterisk/modules/chan_quectel.so

4 0x0000555d52dcc6ee in ast_taskprocessor_execute (tps=0x7fcb58002220) at taskprocessor.c:1302

5 0x0000555d52dd74a6 in execute_tasks (data=0x7fcb58002220) at threadpool.c:1350

6 0x0000555d52dcc6ee in ast_taskprocessor_execute (tps=0x555d55818770) at taskprocessor.c:1302

7 0x0000555d52dd4c42 in threadpool_execute (pool=0x555d55819c00) at threadpool.c:367

8 0x0000555d52dd6bca in worker_active (worker=0x7fcb3c001160) at threadpool.c:1137

9 0x0000555d52dd6903 in worker_start (arg=0x7fcb3c001160) at threadpool.c:1056

10 0x0000555d52de2866 in dummy_start (data=0x7fcb58002760) at utils.c:1607

11 0x00007fcb9ac64ac3 in start_thread (arg=) at ./nptl/pthread_create.c:442

12 0x00007fcb9acf6850 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

this core dump gdb info

hexuanyi commented 1 week ago

[Jun 21 10:34:22] DEBUG[51191]: src/at_queue.c:102 at_queue_add: [quectel0][AT] ↵ [OK] cmds:19 at tail [Jun 21 10:34:22] DEBUG[51191]: src/at_queue.c:214 at_queue_run: [quectel0][AT] → [AT\r] [Jun 21 10:34:22] DEBUG[51185]: threadpool.c:536 grow: Increasing threadpool chan-quectel/pool's size by 1 [Jun 21 10:34:22] DEBUG[51185]: threadpool.c:536 grow: Increasing threadpool chan-quectel/pool's size by 1 [Jun 21 10:34:22] DEBUG[51192]: src/at_response.c:2737 show_response: [quectel0][AT] ← [UNK][AT\r] 'Jun 21 10:34:22] DEBUG[51192]: src/at_response.c:3018 at_response: [quectel0] Ignoring unknown result: 'AT

hexuanyi commented 1 week ago

[Jun 21 10:34:13] DEBUG[51117] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:13] DEBUG[51118] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:13] DEBUG[51119] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:13] DEBUG[51113] threadpool.c: Destroying worker thread 2 [Jun 21 10:34:13] DEBUG[51113] threadpool.c: Destroying worker thread 3 [Jun 21 10:34:13] DEBUG[51113] threadpool.c: Destroying worker thread 4 [Jun 21 10:34:14] DEBUG[51114] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:14] DEBUG[51116] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:14] DEBUG[51113] threadpool.c: Destroying worker thread 0 [Jun 21 10:34:14] DEBUG[51113] threadpool.c: Destroying worker thread 1 [Jun 21 10:34:22] DEBUG[51186] src/chan_quectel.c: [dev-manager] Got scan event [Jun 21 10:34:22] DEBUG[51186] src/chan_quectel.c: [dev-manager][quectel0] Starting device [Jun 21 10:34:22] DEBUG[51191] src/at_queue.c: [quectel0][AT] ↵ [OK] cmds:19 at tail [Jun 21 10:34:22] DEBUG[51191] src/at_queue.c: [quectel0][AT] → [AT\r] [Jun 21 10:34:22] DEBUG[51185] threadpool.c: Increasing threadpool chan-quectel/pool's size by 1 [Jun 21 10:34:22] DEBUG[51185] threadpool.c: Increasing threadpool chan-quectel/pool's size by 1 [Jun 21 10:34:22] DEBUG[51192] src/at_response.c: [quectel0][AT] ← [UNK][AT\r]

hexuanyi commented 1 week ago

[Jun 21 10:33:54] VERBOSE[51111] asterisk.c: Asterisk Ready. [Jun 21 10:34:13] DEBUG[51117] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:13] DEBUG[51118] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:13] DEBUG[51119] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:13] DEBUG[51113] threadpool.c: Destroying worker thread 2 [Jun 21 10:34:13] DEBUG[51113] threadpool.c: Destroying worker thread 3 [Jun 21 10:34:13] DEBUG[51113] threadpool.c: Destroying worker thread 4 [Jun 21 10:34:14] DEBUG[51114] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:14] DEBUG[51116] threadpool.c: Worker thread idle timeout reached. Dying. [Jun 21 10:34:14] DEBUG[51113] threadpool.c: Destroying worker thread 0 [Jun 21 10:34:14] DEBUG[51113] threadpool.c: Destroying worker thread 1 [Jun 21 10:34:22] DEBUG[51186] src/chan_quectel.c: [dev-manager] Got scan event [Jun 21 10:34:22] DEBUG[51186] src/chan_quectel.c: [dev-manager][quectel0] Starting device [Jun 21 10:34:22] VERBOSE[51186] src/chan_quectel.c: [quectel0] Opening data port: /dev/ttyUSB2 [Jun 21 10:34:22] VERBOSE[51186] src/chan_quectel.c: [quectel0] Opening audio port: /dev/ttyUSB1 [Jun 21 10:34:22] VERBOSE[51186] src/chan_quectel.c: [quectel0] Ports opened, initializing... [Jun 21 10:34:22] DEBUG[51191] src/at_queue.c: [quectel0][AT] ↵ [OK] cmds:19 at tail [Jun 21 10:34:22] DEBUG[51191] src/at_queue.c: [quectel0][AT] → [AT\r] [Jun 21 10:34:22] DEBUG[51185] threadpool.c: Increasing threadpool chan-quectel/pool's size by 1 [Jun 21 10:34:22] DEBUG[51185] threadpool.c: Increasing threadpool chan-quectel/pool's size by 1 [Jun 21 10:34:22] DEBUG[51192] src/at_response.c: [quectel0][AT] ← [UNK][AT\r] [Jun 21 10:34:22] DEBUG[51192] src/at_response.c: [quectel0] Ignoring unknown result: 'AT

RoEdAl commented 1 week ago

Sync your repo, rebuild and run again.

hexuanyi commented 1 week ago

OK can you tell me a contact information? I would like to pay to request assistance

hexuanyi commented 1 week ago

Under the AO2 branch, only 1 concurrency can be run

hexuanyi commented 1 week ago

[Jun 22 03:16:35] ERROR[93145]: src/at_response.c:996 handle_clcc: [quectel0] Answered unexisting or multiparty incoming call - idx:3, hanging up! [Jun 22 03:16:35] WARNING[93145]: src/at_response.c:1011 handle_clcc: [quectel0] CLCC (not found) idx:3 dir:0 state:6 mode:0 mpty:off number:16618202190 type:129

RoEdAl commented 1 week ago

If you mean multiparty calls, then they are disabled by default as stated in README.

hexuanyi commented 1 week ago

[Jun 22 03:16:35] ERROR[93145]: src/at_response.c:996 handle_clcc: [quectel0] Answered unexisting or multiparty incoming call - idx:3, hanging up! [Jun 22 03:16:35] WARNING[93145]: src/at_response.c:1011 handle_clcc: [quectel0] CLCC (not found) idx:3 dir:0 state:6 mode:0 mpty:off number:16618202190 type:129

I disconnected when I made a call

RoEdAl commented 1 week ago

Set debug level to 2 and show me debug messages. I must see commands executed by modem and responses.

hexuanyi commented 1 week ago

[Jun 22 07:00:11] WARNING[202358][C-0000000a]: src/channel.c:180 channel_request: [quectel0] Request to call on device which can not make call at this moment [Jun 22 07:00:11] NOTICE[202358][C-0000000a]: app_dial.c:2766 dial_exec_full: Unable to create channel of type 'Quectel' (cause 44 - Requested channel not available) == Everyone is busy/congested at this time (1:0/0/1) this?

RoEdAl commented 1 week ago

Not WARNING nor NOTICE but DEBUG messages such as:

[Jun 22 17:01:06] DEBUG[4823]: src/at_response.c:2737 show_response: [simcom7600][AT+CHUP] ← [+CLCC][+CLCC: 2,1,6,0,0,"608607606",129]
hexuanyi commented 1 week ago

[Jun 22 07:08:48] DEBUG[202190] chan_sip.c: Allocating new SIP dialog for Y2VhZGQ2ZjA4NDE0ZWEyYWQxNTBjMTVkZWZlY2IwYWY. - INVITE (No RTP) [Jun 22 07:08:48] DEBUG[202190][C-00000013] chan_sip.c: Stopping retransmission on 'Y2VhZGQ2ZjA4NDE0ZWEyYWQxNTBjMTVkZWZlY2IwYWY.' of Response 1: Match Found [Jun 22 07:08:48] DEBUG[202190][C-00000013] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f6440005b20' [Jun 22 07:08:48] DEBUG[202190][C-00000013] res_rtp_asterisk.c: (0x7f6440005b20) RTP allocated port 14404 [Jun 22 07:08:48] DEBUG[202190][C-00000013] rtp_engine.c: RTP instance '0x7f6440005b20' is setup and ready to go [Jun 22 07:08:48] DEBUG[202190][C-00000013] res_rtp_asterisk.c: () RTCP setup on RTP instance [Jun 22 07:08:48] VERBOSE[202190][C-00000013] netsock2.c: Using SIP RTP CoS mark 5 [Jun 22 07:08:48] DEBUG[202190][C-00000013] chan_sip.c: Setting NAT on RTP to On [Jun 22 07:08:48] DEBUG[202190][C-00000013] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f63cff03450 [Jun 22 07:08:48] DEBUG[202190][C-00000013] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f63cff03450 [Jun 22 07:08:48] DEBUG[202190][C-00000013] res_rtp_asterisk.c: (0x7f6440005b20) RTCP setting address on RTP instance [Jun 22 07:08:48] DEBUG[202190][C-00000013] res_rtp_asterisk.c: (0x7f6440005b20) RTCP ignoring duplicate property [Jun 22 07:08:48] DEBUG[202190][C-00000013] chan_sip.c: Checking SIP call limits for device 850214 [Jun 22 07:08:48] DEBUG[202190][C-00000013] stasis.c: Topic 'channel:1719040128.26': 0x7f6440017290 created [Jun 22 07:08:48] DEBUG[202190][C-00000013] channel.c: Channel 0x7f644002e6e0 'SIP/850214-00000011' allocated [Jun 22 07:08:48] DEBUG[202652][C-00000013] pbx.c: Launching 'NoOp' [Jun 22 07:08:48] VERBOSE[202652][C-00000013] pbx.c: Executing [13730846859@from-ipphone:1] NoOp("SIP/850214-00000011", "") in new stack [Jun 22 07:08:48] DEBUG[202652][C-00000013] pbx.c: Launching 'Dial' [Jun 22 07:08:48] VERBOSE[202652][C-00000013] pbx.c: Executing [13730846859@from-ipphone:2] Dial("SIP/850214-00000011", "Quectel/quectel0/13730846859") in new stack [Jun 22 07:08:48] DEBUG[202652][C-00000013] app_dial.c: SIP/850214-00000011: Data: Quectel/quectel0/13730846859 [Jun 22 07:08:48] VERBOSE[202652][C-00000013] app_dial.c: Everyone is busy/congested at this time (1:0/0/1) [Jun 22 07:08:48] DEBUG[202652][C-00000013] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Jun 22 07:08:48] DEBUG[202652][C-00000013] app_dial.c: SIP/850214-00000011: Done [Jun 22 07:08:48] DEBUG[202652][C-00000013] pbx.c: Launching 'Hangup' [Jun 22 07:08:48] VERBOSE[202652][C-00000013] pbx.c: Executing [13730846859@from-ipphone:3] Hangup("SIP/850214-00000011", "") in new stack [Jun 22 07:08:48] DEBUG[202652][C-00000013] channel.c: Soft-Hanging (0x20) up channel 'SIP/850214-00000011' [Jun 22 07:08:48] DEBUG[202652][C-00000013] pbx.c: Spawn extension (from-ipphone,13730846859,3) exited non-zero on 'SIP/850214-00000011' [Jun 22 07:08:48] VERBOSE[202652][C-00000013] pbx.c: Spawn extension (from-ipphone, 13431836859, 3) exited non-zero on 'SIP/850214-00000011' [Jun 22 07:08:48] DEBUG[202652][C-00000013] channel.c: Soft-Hanging (0x10) up channel 'SIP/850214-00000011' [Jun 22 07:08:48] DEBUG[202652][C-00000013] channel.c: Channel 0x7f644002e6e0 'SIP/850214-00000011' hanging up. Refs: 2 [Jun 22 07:08:48] DEBUG[202652][C-00000013] chan_sip.c: Hangup call SIP/850214-00000011, SIP callid Y2VhZGQ2ZjA4NDE0ZWEyYWQxNTBjMTVkZWZlY2IwYWY. [Jun 22 07:08:48] DEBUG[202652][C-00000013] res_rtp_asterisk.c: (1719040128.26) RTP Stop [Jun 22 07:08:48] DEBUG[202652][C-00000013] chan_sip.c: AST hangup cause 44 (no match found in SIP) [Jun 22 07:08:48] DEBUG[202652][C-00000013] channel.c: Channel 0x7f644002e6e0 'SIP/850214-00000011' destroying [Jun 22 07:08:48] DEBUG[202652][C-00000013] stasis.c: Topic 'channel:1719040128.26': 0x7f6440017290 destroyed [Jun 22 07:08:48] DEBUG[202149] cdr.c: Finalized CDR for SIP/850214-00000011 - start 1719040128.389771 answer 0.000000 end 1719040128.390733 dur 0.000 bill 1719040128.390 dispo NO ANSWER [Jun 22 07:08:48] DEBUG[202149] cdr.c: Skipping CDR for SIP/850214-00000011 since we weren't answered [Jun 22 07:08:48] DEBUG[202190][C-00000013] chan_sip.c: Stopping retransmission on 'Y2VhZGQ2ZjA4NDE0ZWEyYWQxNTBjMTVkZWZlY2IwYWY.' of Response 2: Match Found

hexuanyi commented 1 week ago

no have this
[Jun 22 17:01:06] DEBUG[4823]: src/at_response.c:2737 show_response: [simcom7600][AT+CHUP] ← [+CLCC][+CLCC: 2,1,6,0,0,"608607606",129]

hexuanyi commented 1 week ago

QuectelStatus=1 [quectel12][USER] ← [+CLCC][+CLCC: 1,1,0,1,0,"",128] [quectel12][USER] ← [+CLCC][+CLCC: 2,1,0,1,0,"",128] quectel12 0 Free WHY?

RoEdAl commented 1 week ago
hexuanyi commented 1 week ago

i try again whithout QuectelStatus

hexuanyi commented 1 week ago

How to determine if the modem is free?

hexuanyi commented 1 week ago

i used
same => n,Set(QuectelStatus=${QUECTEL_STATUS(s:${AVAILEXTEN${counter}})})

RoEdAl commented 1 week ago

I'm sorry but without debug messages from chan_quectel I am not able to help you. And yes, you may use QUECTEL_STATUS to check modem status.

hexuanyi commented 1 week ago

[Jun 22 09:15:45] DEBUG[210330] src/at_queue.c: [quectel0][USER] ↵ [OK][ATD60606060;\r] after head [Jun 22 09:15:45] DEBUG[210330] src/at_queue.c: [quectel0][USER] → [ATD60606060;\r] [Jun 22 09:15:45] DEBUG[210333] src/chan_quectel.c: [handle_expired_reports] Task skipping: no lock [Jun 22 09:15:45] VERBOSE[210332] src/at_response.c: [quectel0][USER] ← [OK][OK] [Jun 22 09:15:45] DEBUG[210332] src/at_queue.c: [quectel0][USER] ↳ [OK] tasks:0 [Jun 22 09:15:45] DEBUG[210332] src/at_response.c: [quectel0] ← [^DSCI][^DSCI: 3,0,2,0,60606060,129] [Jun 22 09:15:45] DEBUG[210333] src/chan_quectel.c: [handle_expired_reports] Task skipping: no lock [Jun 22 09:15:45] DEBUG[210332] src/at_response.c: [quectel0] DSCI - idx:3 dir:0 type:0 state:2 number:60606060 [Jun 22 09:15:45] DEBUG[210332] src/at_queue.c: [quectel0][AT+QHUP] ↵ [OK][AT+QHUP=21,3\r] after head [Jun 22 09:15:45] DEBUG[210332] src/at_queue.c: [quectel0][AT+QHUP] → [AT+QHUP=21,3\r] [Jun 22 09:15:45] DEBUG[210332] src/at_response.c: [quectel0][AT+QHUP] ← [OK][OK] [Jun 22 09:15:45] DEBUG[210333] src/chan_quectel.c: [handle_expired_reports] Task skipping: no lock [Jun 22 09:15:45] DEBUG[210332] src/at_response.c: [quectel0][AT+QHUP] ✓ Successful hangup for call idx:0 [Jun 22 09:15:45] DEBUG[210332] src/at_queue.c: [quectel0][AT+QHUP] ↳ [OK] tasks:0 [Jun 22 09:15:45] DEBUG[210332] src/at_response.c: [quectel0] ← [^DSCI][^DSCI: 3,0,6,0,60606060,129] [Jun 22 09:15:45] DEBUG[210332] src/at_response.c: [quectel0] DSCI - idx:3 dir:0 type:0 state:6 number:60606060

hexuanyi commented 1 week ago

Is this debug useful?

hexuanyi commented 1 week ago

Cannot use s: imsi dial? if use same =>n,Dial(Quectel/s:${mobile_out}/${EXTEN}) error can use same =>n,Dial(Quectel/quectel0/${EXTEN})

hexuanyi commented 1 week ago

[Jun 22 11:30:25] WARNING[3283]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:95 suspended:0 [Jun 22 11:30:35] WARNING[3283]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:96 suspended:0 [Jun 22 11:30:45] WARNING[3283]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:97 suspended:0 [Jun 22 11:30:55] WARNING[3283]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:98 suspended:0 [Jun 22 11:31:05] WARNING[3283]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:99 suspended:0 [Jun 22 11:31:05] WARNING[3283]: taskprocessor.c:1225 taskprocessor_push: The 'chan-quectel/quectel0-0000006f' task processor queue reached 100 scheduled tasks. [Jun 22 11:31:15] WARNING[3283]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:100 suspended:0 asterisk Program stuck

RoEdAl commented 1 week ago
  1. Are you dialing 60606060 number by hand via quectel cmd quectel0 ATD60606060 command? If so, then chan_quectel behaves correctly - just hang up such a forced call. There must be two sides of a call.
  2. Dialing via IMSI is fixed now.
  3. It seems that ao2 branch doesn't solve an original problem. Previously Asterisk got crashed and now in ao2 branch just get stuck. So now you have to find and show me debug messages just before Taskprocessor - size:1 suspended:0 message. And try to find the easiest way to reproduce such a situation.
hexuanyi commented 1 week ago

Taskprocessor - size:100 suspended:0 asterisk Program stuck This problem is difficult to reproduce, and another bug is that sometimes the modem voice is No

hexuanyi commented 1 week ago

[quectel4][AT+QPCMV=1,0] ⍻ Cannot enable audio on serial port this port is ok

hexuanyi commented 1 week ago

Jun 25 02:10:54] ERROR[21232][C-00000373]: frame.c:356 __ast_frdup: Excessive refcount 100000 reached on ao2 object 0x557481be30b8 [Jun 25 02:10:54] ERROR[21232][C-00000373]: frame.c:356 __ast_frdup: FRACK!, Failed assertion Excessive refcount 100000 reached on ao2 object 0x557481be30b8 (0) [Jun 25 02:11:22] WARNING[18233]: src/monitor_thread.c:44 check_taskprocessor: [quectel0] Taskprocessor - size:4 suspended:0

last 50ce6c050ce6c0