[Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [2216950e1@incoming:1] Goto("SIP/sipgate-gmbh-e0-00000000", "83,510") in new stack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Goto (incoming,83,510) [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [83@incoming:510] Macro("SIP/sipgate-gmbh-e0-00000000", "CallExt2Int,SIP/snomvs831&I AX2/vsauer,V1:,,volker@volker-sauer.de") in new stack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:1] AGI("SIP/sipgate-gmbh-e0-00000000", "telefonbuch_reverselook up.php,01796901475") in new stack [Mar 31 13:23:06] VERBOSE[18246] res_agi.c: [Mar 31 13:23:06] -- Launched AGI Script /opt/asterisk/var/lib/asterisk/agi-bin/telefonbuch_reverselookup.php [Mar 31 13:23:06] ERROR[18246] utils.c: write() returned error: Broken pipe [Mar 31 13:23:06] VERBOSE[18246] res_agi.c: [Mar 31 13:23:06] -- AGI Script telefonbuch_reverselookup.php completed, returnin g 0 [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:2] Set("SIP/sipgate-gmbh-e0-00000000", "PICKUPMARK=83") in new stack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:3] NoOp("SIP/sipgate-gmbh-e0-00000000", "83") in new stack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:4] Set("SIP/sipgate-gmbh-e0-00000000", "VOLUME(TX)=") in new st ack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:5] Set("SIP/sipgate-gmbh-e0-00000000", "VOLUME(TX)=") in new st ack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:6] Set("SIP/sipgate-gmbh-e0-00000000", "CALLERID(name)=V1:Sauer ,Volker(cell)") in new stack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:7] JabberSend("SIP/sipgate-gmbh-e0-00000000", "asterisk,volker@ volker-sauer.de,Sie wurden angerufen von "V1:Sauer,Volker(cell)" <01796901475> um Sat Mar 31 13:23:06 2012") in new stack [Mar 31 13:23:06] VERBOSE[18246] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallExt2Int:8] Dial("SIP/sipgate-gmbh-e0-00000000", "SIP/snomvs831&IAX2/vsa uer,,kKtTwW") in new stack [Mar 31 13:23:06] VERBOSE[18246] netsock2.c: [Mar 31 13:23:06] == Using SIP RTP CoS mark 5 [Mar 31 13:23:06] VERBOSE[18246] app_dial.c: [Mar 31 13:23:06] -- Called SIP/snomvs831 [Mar 31 13:23:06] WARNING[18246] app_dial.c: Unable to create channel of type 'IAX2' (cause 20 - Unknown) [Mar 31 13:23:06] VERBOSE[18232] chan_sip.c: [Mar 31 13:23:06] -- Got SIP response 302 "Moved Temporarily" back from 192.168.0.14:5060 [Mar 31 13:23:06] VERBOSE[18246] app_dial.c: [Mar 31 13:23:06] -- Now forwarding SIP/sipgate-gmbh-e0-00000000 to 'Local/85@doLocalCallsPrivat' (thanks to S IP/snomvs831-00000001) [Mar 31 13:23:06] NOTICE[18246] app_dial.c: Not accepting call completion offers from call-forward recipient Local/85@doLocalCallsPrivat-ad88;1 [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [85@doLocalCallsPrivat:1] NoOp("Local/85@doLocalCallsPrivat-ad88;2", "Local/85@d") i n new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [85@doLocalCallsPrivat:2] Set("Local/85@doLocalCallsPrivat-ad88;2", "VOLUME(TX)=") i n new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [85@doLocalCallsPrivat:3] Goto("Local/85@doLocalCallsPrivat-ad88;2", "doLocalCallsGe neric,85,1") in new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Goto (doLocalCallsGeneric,85,1) [Mar 31 13:23:06] NOTICE[18249] ast_expr2.y: argbuf allocated 12 bytes; [Mar 31 13:23:06] NOTICE[18249] ast_expr2.y: argbuf uses 11 bytes; [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [85@doLocalCallsGeneric:1] Set("Local/85@doLocalCallsPrivat-ad88;2", "CALLERID(num)= 01796901475") in new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [85@doLocalCallsGeneric:2] Goto("Local/85@doLocalCallsPrivat-ad88;2", "incoming,85,1 00") in new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Goto (incoming,85,100) [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [85@incoming:100] Macro("Local/85@doLocalCallsPrivat-ad88;2", "CallInt2Int,SIP/snomm 9-2") in new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallInt2Int:1] Set("Local/85@doLocalCallsPrivat-ad88;2", "PICKUPMARK=85") i n new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallInt2Int:2] NoOp("Local/85@doLocalCallsPrivat-ad88;2", "85") in new stac k [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallInt2Int:3] Set("Local/85@doLocalCallsPrivat-ad88;2", "VOLUME(TX)=") in new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallInt2Int:4] Set("Local/85@doLocalCallsPrivat-ad88;2", "VOLUME(TX)=-4") i n new stack [Mar 31 13:23:06] VERBOSE[18249] pbx.c: [Mar 31 13:23:06] -- Executing [s@macro-CallInt2Int:5] Dial("Local/85@doLocalCallsPrivat-ad88;2", "SIP/snomm9-2,,kK wWtTj") in new stack [Mar 31 13:23:06] VERBOSE[18249] netsock2.c: [Mar 31 13:23:06] == Using SIP RTP CoS mark 5 [Mar 31 13:23:06] VERBOSE[18249] app_dial.c: [Mar 31 13:23:06] -- Called SIP/snomm9-2 [Mar 31 13:23:06] VERBOSE[18249] app_dial.c: [Mar 31 13:23:06] -- SIP/snomm9-2-00000002 is ringing [Mar 31 13:23:06] VERBOSE[18246] app_dial.c: [Mar 31 13:23:06] -- Local/85@doLocalCallsPrivat-ad88;1 is ringing [Mar 31 13:23:14] VERBOSE[18249] app_dial.c: [Mar 31 13:23:14] -- SIP/snomm9-2-00000002 answered Local/85@doLocalCallsPrivat-ad88;2 [Mar 31 13:23:14] VERBOSE[18246] app_dial.c: [Mar 31 13:23:14] -- Local/85@doLocalCallsPrivat-ad88;1 answered SIP/sipgate-gmbh-e0-00000000 [Mar 31 13:23:14] VERBOSE[18249] app_macro.c: [Mar 31 13:23:14] == Spawn extension (macro-CallInt2Int, s, 5) exited non-zero on 'Local/85@doLocalCallsPrivat- ad88;2' in macro 'CallInt2Int' [Mar 31 13:23:14] VERBOSE[18249] pbx.c: [Mar 31 13:23:14] == Spawn extension (incoming, 85, 100) exited non-zero on 'Local/85@doLocalCallsPrivat-ad88;2' [Mar 31 13:23:40] ERROR[18246]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 842 (audio_audiohook_write_list): Error obtaining mutex: Invalid argument [Mar 31 13:23:40] ERROR[18246]: lock.c:407 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): mutex '&(audiohook)->lock' freed more times than we've locked! [Mar 31 13:23:40] ERROR[18246]: lock.c:438 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): Error releasing mutex: Invalid argument [Mar 31 13:23:40] ERROR[18246]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 842 (audio_audiohook_write_list): Error obtaining mutex: Invalid argument [Mar 31 13:23:40] ERROR[18246]: lock.c:407 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): mutex '&(audiohook)->lock' freed more times than we've locked! [Mar 31 13:23:40] ERROR[18246]: lock.c:438 __ast_pthread_mutex_unlock: audiohook.c line 861 (audio_audiohook_write_list): Error releasing mutex: Invalid argument [Mar 31 13:23:40] ERROR[18246]: lock.c:280 __ast_pthread_mutex_lock: audiohook.c line 480 (ast_audiohook_update_status): Error obtaining mutex: Invalid argument [Message repeated thousands of times] [Asterisk stopped processing (sip) calls] *CLI> core show locks ======================================================================= === Currently Held Locks ============================================== ======================================================================= === === (): (times locked) === === Thread ID: 0xaf3d9b70 (do_monitor started at [26703] chan_sip.c restart_monitor()) === ---> Lock #0 (chan_sip.c): MUTEX 26675 do_monitor &monlock 0xb68673c0 (1) /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa] /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_lock+0x7c) [0x812902c] /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0x66832) [0xb6816832] /opt/asterisk/sbin/asterisk() [0x81af8ce] /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb7525955] /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769958e] === ---> Waiting for Lock #1 (chan_sip.c): MUTEX 8175 sip_pvt_lock_full chan 0xa390928 (1) /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa] /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_lock+0x7c) [0x812902c] /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0xd0ca) [0xb67bd0ca] /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0x89149) [0xb6839149] /opt/asterisk/sbin/asterisk(ast_sched_runq+0x14d) [0x81952bd] /opt/asterisk/lib/asterisk/modules/chan_sip.so(+0x6683f) [0xb681683f] /opt/asterisk/sbin/asterisk() [0x81af8ce] /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb7525955] /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769958e] === --- ---> Locked Here: channel.c line 2832 (ast_hangup) === ------------------------------------------------------------------- === === Thread ID: 0xaf0dab70 (pbx_thread started at [ 5512] pbx.c ast_pbx_start()) === ---> Lock #0 (channel.c): MUTEX 2832 ast_hangup chan 0xa390928 (1) /opt/asterisk/sbin/asterisk(ast_bt_get_addresses+0x1a) [0x812c8aa] /opt/asterisk/sbin/asterisk(__ast_pthread_mutex_lock+0x7c) [0x812902c] /opt/asterisk/sbin/asterisk(ast_hangup+0x1de) [0x80bf66e] /opt/asterisk/lib/asterisk/modules/app_dial.so(+0xbd1b) [0xb676dd1b] /opt/asterisk/lib/asterisk/modules/app_dial.so(+0xda1d) [0xb676fa1d] /opt/asterisk/sbin/asterisk(pbx_exec+0x10b) [0x8154bdb] /opt/asterisk/sbin/asterisk() [0x816305b] /opt/asterisk/lib/asterisk/modules/app_macro.so(+0x248b) [0xb672948b] /opt/asterisk/sbin/asterisk(pbx_exec+0x10b) [0x8154bdb] /opt/asterisk/sbin/asterisk() [0x816305b] /opt/asterisk/sbin/asterisk() [0x81697ed] /opt/asterisk/sbin/asterisk() [0x816b1de] /opt/asterisk/sbin/asterisk() [0x81af8ce] /lib/i686/cmov/libpthread.so.0(+0x5955) [0xb7525955] /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb769958e] === ------------------------------------------------------------------- === =======================================================================