chan-sccp-b release für asterisk 1.2 und 1.4

... aus dem Stehreif noch nicht.
Kannst du mal in der con auf debug = 10 stellen?
 
Die Ausgaben sind auch mit debug = 10 nicht viel anders (chan_sccp config) - es bricht einfach zwischen dem *letzen* "Device" einlesen und der *ersten* "Line" ab wie im letzen Posting zu sehen, mehr Ausgabe gibt es nicht.

Code:
[...]
[Nov 15 12:46:19]     -- Added speeddial 5: 6004 (6004)
[Nov 15 12:46:19]     -- device = SEP000xxxxxxxx
[Nov 15 12:46:19]     -- Added device 'SEP000xxxxxxxxx' (7960)
Illegal instruction

Mit chan_sccp-20060408+self1.4patch geht es schoen weiter:

Code:
[...]
[Nov 15 12:44:50]     -- Added device 'SEP000xxxxxxxxx' (7960)
[Nov 15 12:44:50]     -- SCCP: Looking for line 6000
[Nov 15 12:44:50]     -- Added line '6000'
[...]

Hier auch nochmal von mir aus die vollstaendige Ausgabe mit der demo-config aus conf/sccp.conf :

Code:
*CLI> module load chan_sccp.so
[Nov 15 12:48:52]   == Platform byte order   : LITTLE ENDIAN
[Nov 15 12:48:52]   == Parsing '/etc/asterisk/sccp.conf': [Nov 15 12:48:52] Found
[Nov 15 12:48:52]     -- GLOBAL: Preferred capability (alaw|ulaw)
[Nov 15 12:48:52]     -- type = 7905
[Nov 15 12:48:52]     -- autologin = line79052,,line79052
[Nov 15 12:48:52]     -- description = Phone7905
[Nov 15 12:48:52]     -- transfer = on
[Nov 15 12:48:52]     -- park = on
[Nov 15 12:48:52]     -- speeddial =
[Nov 15 12:48:52]     -- Added empty speeddial
[Nov 15 12:48:52]     -- speeddial = 1000,name
[Nov 15 12:48:52]     -- Added speeddial 2: name (1000)
[Nov 15 12:48:52]     -- cfwdall = off
[Nov 15 12:48:52]     -- cfwdbusy = off
[Nov 15 12:48:52]     -- dtmfmode = inband
[Nov 15 12:48:52]     -- imageversion = P00405000700
[Nov 15 12:48:52]     -- deny = 0.0.0.0/0.0.0.0
[Nov 15 12:48:52]     -- permit = 192.168.1.5/255.255.255.255
[Nov 15 12:48:52]     -- dnd = on
[Nov 15 12:48:52]     -- trustphoneip = no
[Nov 15 12:48:52]     -- private = on
[Nov 15 12:48:52]     -- device = SEP00119341E684
[Nov 15 12:48:52]     -- Added device 'SEP00119341E684' (7905)
Illegal instruction

Der Asterisk debug level ist sowieso auf 25 bei mir.

bye
-slz
 
Heute ist das erste mal ein Deadlock passiert.

Die interessanten Threads während des Deadlocks waren wohl:
Thread 3 (process 9520):
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7f22e1e in __lll_mutex_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2 0xb7f1eb74 in _L_mutex_lock_218 () from /lib/i686/cmov/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#3 0xb7f1e609 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4 0xb6b6e7c8 in sccp_channel_allocate (l=0x8251878) at /usr/include/asterisk/lock.h:610
#5 0xb6b61b9c in sccp_request (type=0xb63c5f80 "SCCP", format=8, data=0xb63c6be4, cause=0xb63c6e44) at chan_sccp.c:144
#6 0x08076eb9 in ast_request_with_uniqueid (type=0xb63c5f80 "SCCP", format=8, data=0xb63c6be4, cause=0xb63c6e44, uniqueid=0x0) at channel.c:3277
#7 0x08076f8d in ast_request (type=0xb63c5f80 "SCCP", format=72, data=0xb63c6be4, cause=0xb63c6e44) at channel.c:3293
#8 0xb6acf97a in dial_exec_full (chan=0x821eb10, data=0xb63caf58, peerflags=0xb63c6e84, continue_exec=0x0) at app_dial.c:1127
#9 0xb6ad46bd in dial_exec (chan=0x821eb10, data=0xb63caf58) at app_dial.c:1733
#10 0x080abdb4 in pbx_exec (c=0x821eb10, app=0x81da960, data=0xb63caf58) at pbx.c:532
#11 0x080afc74 in pbx_extension_helper (c=0x821eb10, con=<value optimized out>, context=0x821ec90 "droste-queue", exten=0x821ece0 "3", priority=2, label=0x0,
callerid=0x815a900 "unbekannt", action=E_SPAWN) at pbx.c:1833
#12 0x080b0cbd in __ast_pbx_run (c=0x821eb10) at pbx.c:2388
#13 0x080b1f0e in pbx_thread (data=0x821eb10) at pbx.c:2603
#14 0x080d78c7 in dummy_start (data=0x81e8bc8) at utils.c:806
#15 0xb7f1c46b in start_thread () from /lib/i686/cmov/libpthread.so.0
#16 0xb7e394de in clone () from /lib/i686/cmov/libc.so.6

Thread 2 (process 9525):
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7f22e1e in __lll_mutex_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2 0xb7f1eb74 in _L_mutex_lock_218 () from /lib/i686/cmov/libpthread.so.0
#3 0xb7f1e609 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4 0xb6b6e7c8 in sccp_channel_allocate (l=0x8251878) at /usr/include/asterisk/lock.h:610
#5 0xb6b61b9c in sccp_request (type=0xb64b5f80 "SCCP", format=8, data=0xb64b6be4, cause=0xb64b6e44) at chan_sccp.c:144
#6 0x08076eb9 in ast_request_with_uniqueid (type=0xb64b5f80 "SCCP", format=8, data=0xb64b6be4, cause=0xb64b6e44, uniqueid=0x0) at channel.c:3277
#7 0x08076f8d in ast_request (type=0xb64b5f80 "SCCP", format=72, data=0xb64b6be4, cause=0xb64b6e44) at channel.c:3293
#8 0xb6acf97a in dial_exec_full (chan=0x8244d38, data=0xb64baf58, peerflags=0xb64b6e84, continue_exec=0x0) at app_dial.c:1127
#9 0xb6ad46bd in dial_exec (chan=0x8244d38, data=0xb64baf58) at app_dial.c:1733
#10 0x080abdb4 in pbx_exec (c=0x8244d38, app=0x81da960, data=0xb64baf58) at pbx.c:532
#11 0x080afc74 in pbx_extension_helper (c=0x8244d38, con=<value optimized out>, context=0x8244eb8 "droste-queue", exten=0x8244f08 "3", priority=2, label=0x0,
callerid=0x821bbe0 "unbekannt", action=E_SPAWN) at pbx.c:1833
#12 0x080b0cbd in __ast_pbx_run (c=0x8244d38) at pbx.c:2388
#13 0x080b1f0e in pbx_thread (data=0x8244d38) at pbx.c:2603
#14 0x080d78c7 in dummy_start (data=0x821f6a8) at utils.c:806
#15 0xb7f1c46b in start_thread () from /lib/i686/cmov/libpthread.so.0
#16 0xb7e394de in clone () from /lib/i686/cmov/libc.so.6

Dort wird von zwei Threads sccp_channel_allocate mit der selben Line aufgerufen.
 
Das klingt nicht gut. Da weiss ich ja was ich heute abend zu tun hab ;)
Danke für das log.

Welche Asterisk-Version und welches chan_sccp?
 
Zuletzt bearbeitet:
Deadlock

Das klingt nicht gut. Da weiss ich ja was ich heute abend zu tun hab ;)
Danke für das log.

Welche Asterisk-Version und welches chan_sccp?

Asterisk 1.4.13 mit chan_sccp 20071111
Ich habe noch den ganzen bt der Threads angehängt, jedenfalls alle SCCP Threads. An den anderen lag es ganz sicher nicht, denn per Zap und SIP konnte man noch problemlos anrufen.
 

Anhänge

  • bt_threads_chansccp_deadlock.txt
    5.8 KB · Aufrufe: 5
Mir ist gerade noch aufgefallen, dass Thread 7 auch die gleiche Line benutzt, und der hat die kleinste Prozess-ID, was nicht unbedingt etwas bedeutet, hier aber ein Indiz ist.

In sccp_channel.c, Funktion sccp_transfer_complete:

Nun ist es ja so, dass ich wegen der Segfaults bei Blindtransferen ast_mutex_lock(&d->lock) aufrufe, bevor ast_chan_hangup aufgerufen wird, was auch super funktioniert. Ohne den Mutex anzuwenden, kam es ab und zu zu Segfaults bei ast_chan_hangup, weil peer->owner plötzlich NULL war. Möglicherweise löst genau das nun aber diesen Deadlock aus. Ich probiere mal so:

ast_mutex_lock(&d->lock);
if (peer->owner) {
ast_mutex_unlock(&d->lock);
ast_queue_hangup(peer->owner);
}
else {
sccp_log(1)(VERBOSE_PREFIX_3 "Peer owner disappeared! Can't free ressources\n");
ast_mutex_unlock(&d->lock);
return;
}
ast_mutex_unlock(&transferee->lock);

ast_mutex_lock(&d->lock);
d->transfer_channel = NULL;
ast_mutex_unlock(&d->lock);

Es kann allerdings dauern, bis ich merke, ob das so besser ist als der aktuelle Code.
 
Danke Dir. Jetzt haben wir wenigstens erst mal einen Anhaltspunkt.
 
@masterSLZ

Kannst du ein Backtrace hochladen?
 
Und wieder ein Segfault...

bt:
Code:
#0  0xb6c36466 in sccp_dev_send (d=0x0, r=0x821a538) at sccp_device.c:164
#1  0xb6c3314f in sccp_channel_send_callinfo (c=0x822d200) at sccp_channel.c:171
#2  0xb6c3da8d in sccp_pbx_hangup (ast=0x822cc88) at sccp_pbx.c:324
#3  0x0807a2b5 in ast_hangup (chan=0x822cc88) at channel.c:1783
#4  0xb6b97574 in dial_exec_full (chan=0x81fd6f0, data=0xb6384f58, peerflags=0xb6380e84, continue_exec=0x0) at app_dial.c:581
#5  0xb6b9a6bd in dial_exec (chan=0x81fd6f0, data=0xb6384f58) at app_dial.c:1733
#6  0x080abdb4 in pbx_exec (c=0x81fd6f0, app=0x81d9be0, data=0xb6384f58) at pbx.c:532
#7  0x080afc74 in pbx_extension_helper (c=0x81fd6f0, con=<value optimized out>, context=0x81fd870 "droste-incoming", exten=0x81fd8c0 "49", priority=11, label=0x0,
    callerid=0x82195e0 "unbekannt", action=E_SPAWN) at pbx.c:1833
#8  0x080b0cbd in __ast_pbx_run (c=0x81fd6f0) at pbx.c:2388
#9  0x080b1f0e in pbx_thread (data=0x81fd6f0) at pbx.c:2603
#10 0x080d78c7 in dummy_start (data=0x81feb68) at utils.c:806
#11 0xb7ee146b in start_thread () from /lib/i686/cmov/libpthread.so.0
#12 0xb7dfe4de in clone () from /lib/i686/cmov/libc.so.6

patch:
Code:
--- chan_sccp_20071111/sccp_channel.c   2007-11-08 19:31:49.000000000 +0100
+++ chan_sccp_20071111-mod/sccp_channel.c       2007-11-16 14:07:17.992317447 +0100
@@ -168,7 +168,12 @@
     r->msg.CallInfoMessage.lel_callRef  = htolel(c->callid);
     r->msg.CallInfoMessage.lel_callType = htolel(c->calltype);
     r->msg.CallInfoMessage.lel_callSecurityStatus = htolel(SKINNY_CALLSECURITYSTATE_UNKNOWN);
-    sccp_dev_send(c->line->device, r);
+
+    if (c->line->device)
+       sccp_dev_send(c->line->device, r);
+    else
+       return;
+
     sccp_log(10)(VERBOSE_PREFIX_3 "%s: Send callinfo for %s channel %d\n", c->line->device->id, skinny_calltype2str(c->calltype), c->callid);
 }
 
dann doch aber besser so:
Code:
--- chan_sccp_20071111/sccp_channel.c   2007-11-08 19:31:49.000000000 +0100
+++ chan_sccp_20071111-mod/sccp_channel.c       2007-11-16 14:07:17.992317447 +0100
@@ -168,7 +168,12 @@
     r->msg.CallInfoMessage.lel_callRef  = htolel(c->callid);
     r->msg.CallInfoMessage.lel_callType = htolel(c->calltype);
     r->msg.CallInfoMessage.lel_callSecurityStatus = htolel(SKINNY_CALLSECURITYSTATE_UNKNOWN);
-    sccp_dev_send(c->line->device, r);
+
+    if (c->line->device){
+       sccp_dev_send(c->line->device, r);
+       sccp_log(10)(VERBOSE_PREFIX_3 "%s: Send callinfo for %s channel %d\n", c->line->device->id, skinny_calltype2str(c->calltype), c->callid);
+    }else
+       return;
+
 
 }
 
Eine kurze Frage. ist es mit diesem letzten Release eventuell Möglich die Beleuchtung der Speedial-Tasten zu steuern? Also z.B. ich lege auf eine Taste die Mailbox und solange Sie aktiv ist soll die Lampe brennen... Mein Problem derzeit: Ich setze über ne extension ne Rufumleitung zur Mailbox und lasse mit mit SetMessage auf dem Telefon " AB eingeschaltet" einblenden. Da aber das Telefon so eingerichtet ist das e serst 2 mal klingelt bevor der AB dran geht überschreibt er mir die SET MEssage Meldung mit "Anrufe in Abwesenheit" und es ist dann nicht mehr ersichtlich ob der AB ein oder aus ist.

Villeicht weiß jemand hier dazu ne Lösung oder ein BestPractise ;-)
 
Hallo Mysterious,

so weit sind wir noch nicht das wir so etwas mit anbieten können.
Dein Vorhaben sollte aber mit dem manuellen setzten des device_state möglich sein.
 
Okay, könntest du mir kurz erklären wie ich device_states einsetze bzw. wie Sie in den Configs auszusehen haben? Das wäre Klasse? Oder soll ich nen eigenen Thread zu dem Thema eröffen um die Übersicht uz wahren?
 
SetMessage wird von "Anruf in Abwesenheit" überschrieben, kommt aber danach wieder. Das ist Absicht so...
 
Oh, okay wenn das so ist dann ist das ja perfekt. Muss zugeben das ich net probiert hatte die Anrufe in Abwesenheit zu löschen und dann zu schauen was im Display steht.
 
Und wieder ein Segfault!

Code:
#0  0xb7f70bc0 in pthread_mutex_trylock () from /lib/i686/cmov/libpthread.so.0
#1  0x080805d2 in ast_queue_hangup (chan=0x4f5a3c39) at /tmp/buildd/asterisk-1.4.13~dfsg/include/asterisk/lock.h:615
#2  0xb6cc1493 in sccp_channel_transfer_complete (c=0xb61011c8) at sccp_channel.c:935
#3  0xb6cc2852 in sccp_channel_transfer (c=0xb61011c8) at sccp_channel.c:798
#4  0xb6ccda1d in sccp_sk_transfer (d=0x81f8750, l=0x81feec0, c=0x758b) at sccp_softkeys.c:94
#5  0xb6cbe899 in sccp_handle_soft_key_event (s=0xb6600968, r=0xb61007c8) at sccp_actions.c:1302
#6  0xb6cb2fce in sccp_handle_message (r=0xb61007c8, s=0xb6600968) at chan_sccp.c:607
#7  0xb6cceba4 in sccp_socket_thread (ignore=0x0) at sccp_socket.c:326
#8  0x080d78c7 in dummy_start (data=0x8202bf0) at utils.c:806
#9  0xb7f6e46b in start_thread () from /lib/i686/cmov/libpthread.so.0
#10 0xb7e8b4de in clone () from /lib/i686/cmov/libc.so.6

Wieder bei einem Blindtransfer und wieder bei ast_queue_hangup. Ich lasse das jetzt einfach weg, es räumt ja doch irgendein anderer Thread auf. Mal sehen.
 
Ich habe einen Deadlock entdeckt!

Die Funktion sccp_channel_find_bystate_on_device:
sccp_channel_t * sccp_channel_find_bystate_on_device(sccp_device_t * d, uint8_t state) {
sccp_channel_t * c = NULL;
sccp_line_t * l;
if (!d)
return NULL;
// sccp_log(10)(VERBOSE_PREFIX_3 "%s: Looking for a channel with state \"%s\" (%d) on device\n", d->id, sccp_indicate2str(state), state);

ast_mutex_lock(&GLOB(channels_lock));
ast_mutex_lock(&d->lock);
l = d->lines;
while (l) {
c = sccp_channel_find_bystate_on_line(l, state);
if (c)
break;
l = l->next_on_device;
}
ast_mutex_unlock(&d->lock);
ast_mutex_unlock(&GLOB(channels_lock));
if (c)
sccp_log(10)(VERBOSE_PREFIX_3 "%s: Found channel (%d) with state \"%s\" (%d) on device\n", d->id, c->callid, sccp_indicate2str(state), state);
return c;
}

Die Funktion sccp_channel_delete
Code:
void sccp_channel_delete(sccp_channel_t * c) {
        ast_mutex_lock(&GLOB(channels_lock));
        sccp_channel_delete_no_lock(c);
        ast_mutex_unlock(&GLOB(channels_lock));
}

Wie man klar sieht, machen beide Funktionen ast_mutex_lock(&GLOB(channels_lock)), auch locken beide dann die einzelnen Devices mit ast_mutex_lock(&d->lock);

Hier die beteiligten Threads:
Code:
Thread 38 (process 21713):
#0  0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1  0xb7fc3e1e in __lll_mutex_lock_wait () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#2  0xb7fbfb74 in _L_mutex_lock_218 () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#3  0xb7fbf609 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#4  0xb6d0d45b in sccp_channel_find_bystate_on_device (d=0x81f4ea0, state=4 '\004') at /usr/include/asterisk/lock.h:610
     c = (sccp_channel_t *) 0x0
     l = <value optimized out>
#5  0xb6cf91c2 in sccp_devicestate (data=0xb7d8c2f5) at chan_sccp.c:268
     l = (sccp_line_t *) 0x54d1
     res = 1
#6  0x08089acf in ast_device_state (device=0x82188fc "SCCP/13") at devicestate.c:172
     buf = 0xb7d8c2f5 "13"
     chan_tech = <value optimized out>
     res = <value optimized out>
     tech = <value optimized out>
     __PRETTY_FUNCTION__ = "ast_device_state"
#7  0x08089c87 in do_state_change (device=0xfffffe00 <Address 0xfffffe00 out of bounds>, cid_num=0x54d1 <Address 0x54d1 out of bounds>, cid_name=0x0) at devicestate.c:287
     state = <value optimized out>
     devcb = <value optimized out>
     __PRETTY_FUNCTION__ = "do_state_change"
#8  0x0808a39d in do_devstate_changes (data=0x0) at devicestate.c:375
     cur = (struct state_change *) 0x8218858
#9  0x080d78c7 in dummy_start (data=0x81525d8) at utils.c:806
     __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {135603688, 0, -1210528880, -1210530856, -1517879151, 250698222}, __mask_was_saved = 0}}, __pad = {0xb7d8c490,
    0x0, 0x0, 0x0}}
     __cancel_arg = (void *) 0xb7d8cb90
     not_first_call = <value optimized out>
     ret = <value optimized out>
#10 0xb7fbd46b in start_thread () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#11 0xb7eda4de in clone () from /lib/i686/cmov/libc.so.6
No symbol table info available.
#0  0xffffe410 in __kernel_vsyscall ()

und

Code:
Thread 15 (process 21738):
#0  0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1  0xb7fc3e1e in __lll_mutex_lock_wait () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#2  0xb7fbfb74 in _L_mutex_lock_218 () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#3  0xb7fbf609 in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#4  0xb6d07b59 in sccp_channel_delete (c=0xb6002d20) at /usr/include/asterisk/lock.h:610
No locals.
#5  0xb6d10b91 in sccp_pbx_hangup (ast=0xb6000920) at sccp_pbx.c:346
     c = (sccp_channel_t *) 0xb6002d20
     l = (sccp_line_t *) 0x81ff590
     d = (sccp_device_t *) 0x81f4ea0
     __PRETTY_FUNCTION__ = "sccp_pbx_hangup"
#6  0x0807a2b5 in ast_hangup (chan=0xb6000920) at channel.c:1783
     res = <value optimized out>
     cdr = (struct ast_cdr *) 0xb6001a30
     __PRETTY_FUNCTION__ = "ast_hangup"
#7  0xb6d07f60 in sccp_channel_endcall (c=0xb6002d20) at sccp_channel.c:424
     d = (sccp_device_t *) 0x81f4ea0
     ast = (struct ast_channel *) 0xb6000920
     res = 0 '\0'
#8  0xb6d0b273 in sccp_line_kill (l=0x81ff590) at sccp_line.c:39
     c = (sccp_channel_t *) 0xfffffe00
     t = (sccp_channel_t *) 0x0
#9  0xb6d14d06 in sccp_socket_thread (ignore=0x0) at sccp_socket.c:125
     fset = {fds_bits = {0, 0, 64, 0 <repeats 29 times>}}
     res = <value optimized out>
     maxfd = 81
     now = 1195643465
     s = (sccp_session_t *) 0x8217660
     s1 = (sccp_session_t *) 0x821d128
     m = <value optimized out>
     tv = {tv_sec = 0, tv_usec = 50000}
     sigs = {__val = {138432515, 0 <repeats 31 times>}}
     attr = {__size = "\000\000\000\000\000\000\000\000\001\000\000\000\000\020", '\0' <repeats 21 times>, __align = 0}
     __PRETTY_FUNCTION__ = "sccp_socket_thread"
#10 0x080d78c7 in dummy_start (data=0x8202c40) at utils.c:806
     __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {136326224, 0, -1227936880, -1227938856, -1975058285, 250698222}, __mask_was_saved = 0}}, __pad = {0xb6cf2490,
    0x0, 0x0, 0x0}}
     __cancel_arg = (void *) 0xb6cf2b90
     not_first_call = <value optimized out>
     ret = <value optimized out>
#11 0xb7fbd46b in start_thread () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#12 0xb7eda4de in clone () from /lib/i686/cmov/libc.so.6
No symbol table info available.
#0  0xffffe410 in __kernel_vsyscall ()

Man sieht, dass beide Threads auf dasselbe Device zugreifen wollen, und dabei kam es wohl zu einem Deadlock.
 
in welcher Situation ist dieser aufgetreten?
 
Holen Sie sich 3CX - völlig kostenlos!
Verbinden Sie Ihr Team und Ihre Kunden Telefonie Livechat Videokonferenzen

Gehostet oder selbst-verwaltet. Für bis zu 10 Nutzer dauerhaft kostenlos. Keine Kreditkartendetails erforderlich. Ohne Risiko testen.

3CX
Für diese E-Mail-Adresse besteht bereits ein 3CX-Konto. Sie werden zum Kundenportal weitergeleitet, wo Sie sich anmelden oder Ihr Passwort zurücksetzen können, falls Sie dieses vergessen haben.