[asterisk-bugs] [JIRA] (ASTERISK-18726) CDR processing appears to hang during channel hangup update
Matt Jordan (JIRA)
noreply at issues.asterisk.org
Tue Jan 15 09:48:45 CST 2013
[ https://issues.asterisk.org/jira/browse/ASTERISK-18726?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Matt Jordan closed ASTERISK-18726.
----------------------------------
Resolution: Not A Bug
> CDR processing appears to hang during channel hangup update
> -----------------------------------------------------------
>
> Key: ASTERISK-18726
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-18726
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: CDR/General
> Affects Versions: 10.0.0-beta2
> Environment: Ubuntu Lucid 10.4, Pessimistic mode
> Reporter: Matt Jordan
> Severity: Minor
>
> There are sporadic failures of the thread post-test condition during Pessimistic mode Asterisk Test Suite execution, in which pbx_thread(s) are detected as being present at the end of a test after a channel hangup has been requested. Typically, the delta between when the channel hangup requests are issued (via the dialplan Hangup application) and when the post-test condition fires to check for threads is approximately 7 - 10 seconds.
> Sometimes, the pbx thread is still present in the system after a soft hang up has been requested on the channel. This appears to occur when the CDR record for RADIUS fails to be written. One of the log files (linked to later in this issue) is shown below.
> Dialplan issues its Hangup request:
> [Oct 17 10:01:46] DEBUG[11924] pbx.c: Launching 'Hangup'
> [Oct 17 10:01:46] VERBOSE[11924] pbx.c: -- Executing [8052 at voicemail:4] Hangup("SIP/ast2-00000000", "") in new stack
> [Oct 17 10:01:46] DEBUG[11924] pbx.c: Spawn extension (voicemail,8052,4) exited non-zero on 'SIP/ast2-00000000'
> [Oct 17 10:01:46] VERBOSE[11924] pbx.c: == Spawn extension (voicemail, 8052, 4) exited non-zero on 'SIP/ast2-00000000'
> [Oct 17 10:01:46] DEBUG[11924] channel.c: Soft-Hanging up channel 'SIP/ast2-00000000'
> [Oct 17 10:01:46] DEBUG[11924] channel.c: Hanging up channel 'SIP/ast2-00000000'
> [Oct 17 10:01:46] DEBUG[11924] chan_sip.c: Hanging up zombie call. Be scared.
> [Oct 17 10:01:46] DEBUG[11924] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1c09558'
> [Oct 17 10:01:46] DEBUG[11924] netsock2.c: Splitting '127.0.0.2:5060' into...
> [Oct 17 10:01:46] DEBUG[11924] netsock2.c: ...host '127.0.0.2' and port '5060'.
> [Oct 17 10:01:46] DEBUG[11924] chan_sip.c: Trying to put 'BYE sip:ast' onto UDP socket destined for 127.0.0.2:5060
> [Oct 17 10:01:46] DEBUG[11831] chan_sip.c: = Looking for Call ID: 79b856c028ff2d06444e131c73e983b4 at 127.0.0.2:5060 (Checking To) --From tag as69a712bb --To-tag as4c58ee84
> [Oct 17 10:01:46] DEBUG[11831] chan_sip.c: Stopping retransmission on '79b856c028ff2d06444e131c73e983b4 at 127.0.0.2:5060' of Request 102: Match Found
> [Oct 17 10:01:46] DEBUG[11831] chan_sip.c: Destroying SIP dialog 79b856c028ff2d06444e131c73e983b4 at 127.0.0.2:5060
> [Oct 17 10:01:46] DEBUG[11831] rtp_engine.c: Destroyed RTP instance '0x1c09558'
> [Oct 17 10:01:46] DEBUG[11924] cdr_radius.c: Unable to create RADIUS record. CDR not recorded!
> At this point, thread 11924 'stops' processing. For all intents and purposes (and from the perspective of the log file), Asterisk isn't doing much for the next 7 seconds.
> [Oct 17 10:01:53] VERBOSE[11801] asterisk.c: -- Remote UNIX connection
> [Oct 17 10:01:53] VERBOSE[11973] asterisk.c: -- Remote UNIX connection disconnected
> [Oct 17 10:01:53] VERBOSE[11801] asterisk.c: -- Remote UNIX connection
> [Oct 17 10:01:53] VERBOSE[11982] asterisk.c: -- Remote UNIX connection disconnected
> [Oct 17 10:01:53] VERBOSE[11801] asterisk.c: -- Remote UNIX connection
> [Oct 17 10:01:53] VERBOSE[11988] asterisk.c: -- Remote UNIX connection disconnected
> [Oct 17 10:01:53] VERBOSE[11801] asterisk.c: -- Remote UNIX connection
> These AMI connections are the various post-test conditions firing. At this point, we'll have failed the test as the pbx_thread 11924 hasn't yet exited. We then start the Asterisk shut down process.
> [Oct 17 10:01:53] VERBOSE[11994] pbx.c: == Unregistered application 'ADSIProg'
> [Oct 17 10:01:53] VERBOSE[11994] pbx.c: == Unregistered application 'AlarmReceiver'
> [Oct 17 10:01:53] VERBOSE[11994] pbx.c: == Unregistered application 'AMD'
> [Oct 17 10:01:53] VERBOSE[11994] pbx.c: == Unregistered application 'Authenticate'
> Sometime later, pbx_thread 11924 comes out of its coma and starts processing additional CDR destinations.
> [Oct 17 10:01:53] VERBOSE[11994] bridging.c: == Unregistered bridge technology simple_bridge
> [Oct 17 10:01:53] VERBOSE[11994] bridging.c: == Unregistered bridge technology softmix
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '2011-10-17 10:00:58'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '"Anonymous" <ast2>'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is 'voicemail'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is 'SIP/ast2-00000000'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '(null)'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is 'Hangup'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '(null)'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '48'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '48'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is 'ANSWERED'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is 'DOCUMENTATION'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '(null)'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '1318863658.0'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '(null)'
> [Oct 17 10:01:58] DEBUG[11924] pbx.c: Function result is '(null)'
> [Oct 17 10:01:58] DEBUG[11924] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2011-10-17 10:00:58','"Anonymous" <ast2>','voicemail','SIP/ast2-00000000','','Hangup','','48','48','ANSWERED','DOCUMENTATION','','1318863658.0','','')
> [Oct 17 10:02:00] VERBOSE[11994] cdr.c: == Unregistered 'Adaptive ODBC' CDR backend
> [Oct 17 10:02:00] VERBOSE[11994] cdr.c: == Unregistered 'csv' CDR backend
> [Oct 17 10:02:00] VERBOSE[11994] cdr.c: == Unregistered 'cdr-custom' CDR backend
> [Oct 17 10:02:00] VERBOSE[11994] cdr.c: == Unregistered 'radius' CDR backend
> [Oct 17 10:02:00] VERBOSE[11994] cdr.c: == Unregistered 'sqlite' CDR backend
> Note that this delay does not occur every time the write to the RADIUS CDR fails; other logs show the sqllite3 CDR being written to immediately after the failed write. However, in this example, it appears as if something was locked or suspended and was only triggered again when the CDR engine terminate was called.
> Logs:
> http://bamboo.asterisk.org/artifact/TESTING-ASTTRUNKPESSIMISTIC/UBUNTULUCID/build-8/testsuite/apps/voicemail/check_voicemail_forward_with_prepend/ast1/var/log/asterisk/full.txt
> http://bamboo.asterisk.org/artifact/TESTING-ASTTRUNKPESSIMISTIC/UBUNTULUCID/build-8/testsuite/apps/voicemail/check_voicemail_forward_with_prepend/ast2/var/log/asterisk/full.txt
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the asterisk-bugs
mailing list