Confused about CDR entries - erroneous? 's' entries

Hi,

(I think) since upgrading to 1.4.5/6 I’m seeing extra entries in my CDR log. This occurs on incoming and outgoing calls. The entries are logged against a destination of ‘s’

Also, if I call a RINGGROUP then all of the unanswered extensions log against ‘s’ too and no callerid substitution is performed either.

[size=75]2007-07-02 00:06:13 SIP/100-08… 08003289393 08003289393 s NO ANSWER 00:05
2007-07-02 00:06:13 SIP/102-08… 08003289393 08003289393 s NO ANSWER 00:05
2007-07-02 00:06:13 SIP/715180… 08003289393 “Inbound-715180” <08003289393> s ANSWERED 00:15
2007-07-02 00:05:44 SIP/101-b7… 01XXXX15180 “TheStones” <01XXXX15180> s ANSWERED 00:24
2007-07-02 00:03:06 SIP/012808… 101 101 s NO ANSWER 00:01
2007-07-02 00:03:05 SIP/084497… 101 101 s NO ANSWER 00:00
2007-07-02 00:03:05 SIP/101-b7… 101 “HP 7940” <101> 917070 BUSY 00:02
2007-07-02 00:02:30 SIP/012808… 101 101 s NO ANSWER 00:01
2007-07-02 00:02:29 SIP/101-b7… 101 “HP 7940” <101> 917070 BUSY 00:02
2007-07-02 00:02:29 SIP/084497… 101 101 s NO ANSWER 00:01
2007-07-02 00:02:16 SIP/084497… 101 101 s NO ANSWER 00:00
2007-07-02 00:02:16 SIP/012808… 101 101 s NO ANSWER 00:01
2007-07-02 00:02:15 SIP/101-b7… 101 “HP 7940” <101> 917070 BUSY 00:02
2007-07-01 23:18:13 SIP/100-08… 100 “Stone Family” <100> 599 NO ANSWER 00:09
2007-07-01 23:18:13 SIP/101-08… 100 100 s NO ANSWER 00:09
2007-07-01 23:18:13 SIP/102-08… 100 100 s NO ANSWER 00:09
2007-07-01 23:18:13 SIP/100-08… 100 100 s NO ANSWER 00:00
2007-07-01 23:14:34 SIP/101-08… 07XXXXX5666 07XXXXX5666 s NO ANSWER 00:13
2007-07-01 23:14:24 SIP/habile… 07XXXXX5666 “Chris (Mobile)” <07XXXXX5666> 601 ANSWERED 00:23
2007-07-01 23:10:38 SIP/102-08… 07XXXXX5666 07XXXXX5666 s NO ANSWER 00:10
2007-07-01 23:10:38 SIP/101-08… 07XXXXX5666 07XXXXX5666 s NO ANSWER 00:10
2007-07-01 23:10:37 SIP/715180… 07XXXXX5666 “Chris (Mobile)” <07XXXXX5666> 599 ANSWERED 01:22[/size]

I see the following in the log, but I don’t understand why cdr_addon_mysql gets called during the processing of the hangup in the CANCEL. I think this is what is causing the extra/incorrect entries…

[size=75][Jul 2 10:16:22] VERBOSE[17856] logger.c: – SIP/01xxxxxx201-088cd5a8 is making progress passing it to SIP/101-b7c0d358
[Jul 2 10:16:23] DEBUG[17856] rtp.c: Ooh, format changed from unknown to alaw
[Jul 2 10:16:23] DEBUG[17856] rtp.c: Created smoother: format: 8 ms: 20 len: 160
[Jul 2 10:16:26] DEBUG[29096] chan_sip.c: = No match Their Call ID: 7302ca7035469520188b585742bb609e@draytel.org Their Tag as7080d69d Our tag: as5c8cf532
[Jul 2 10:16:26] DEBUG[29096] chan_sip.c: = Found Their Call ID: c126d729-81a922a@192.168.1.101 Their Tag 916dab1df256aec6o0 Our tag: as4939ff5e
[Jul 2 10:16:26] DEBUG[29096] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL
[Jul 2 10:16:26] DEBUG[29096] chan_sip.c: Setting SIP_ALREADYGONE on dialog c126d729-81a922a@192.168.1.101
[Jul 2 10:16:26] DEBUG[17856] rtp.c: Channel ‘’ has no RTP, not doing anything
[color=red][Jul 2 10:16:26] DEBUG[17856] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jul 2 10:16:26] DEBUG[17856] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2007-07-02 10:16:21’,‘101’,‘101’,‘s’,‘from-pstn’, ‘SIP/01xxxxxx201-088cd5a8’,’’,’’,’’,5,0,‘NO ANSWER’,3,’’)[/color]
[Jul 2 10:16:26] DEBUG[17856] channel.c: Hanging up channel ‘SIP/01xxxxxx201-088cd5a8’
[Jul 2 10:16:26] DEBUG[17856] chan_sip.c: Hangup call SIP/01xxxxxx201-088cd5a8, SIP callid 7302ca7035469520188b585742bb609e@draytel.org)
[Jul 2 10:16:26] DEBUG[17856] chan_sip.c: Hanging up channel in state Down (not UP)
[Jul 2 10:16:26] DEBUG[17856] chan_sip.c: Acked pending invite 103
[Jul 2 10:16:26] DEBUG[17856] chan_sip.c: Stopping retransmission on '7302ca7035469520188b585742bb609e@draytel.org’ of Request 103: Match Not Found
[Jul 2 10:16:26] DEBUG[17856] devicestate.c: Notification of state change to be queued on device/channel SIP/01xxxxxx201-088cd5a8
[Jul 2 10:16:26] DEBUG[17856] app_dial.c: Exiting with DIALSTATUS=CANCEL.
[Jul 2 10:16:26] DEBUG[17856] app_macro.c: Spawn extension (macro-dialout-trunk,s,23) exited non-zero on ‘SIP/101-b7c0d358’ in macro ‘dialout-trunk’
[Jul 2 10:16:26] DEBUG[17856] pbx.c: Spawn extension (macro-dialout-trunk,s,23) exited non-zero on ‘SIP/101-b7c0d358’
[Jul 2 10:16:26] VERBOSE[17856] logger.c: == Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on ‘SIP/101-b7c0d358’
[Jul 2 10:16:26] DEBUG[17856] pbx.c: Launching ‘Macro’
[Jul 2 10:16:26] VERBOSE[17856] logger.c: – Executing [h@macro-dialout-trunk:1] Macro(“SIP/101-b7c0d358”, “hangupcall”) in new stack
[Jul 2 10:16:26] DEBUG[17856] pbx.c: Launching ‘ResetCDR’
[Jul 2 10:16:26] VERBOSE[17856] logger.c: – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/101-b7c0d358”, “w”) in new stack
[Jul 2 10:16:26] DEBUG[29067] devicestate.c: No provider found, checking channel drivers for SIP - 01xxxxxx201
[Jul 2 10:16:26] DEBUG[29067] chan_sip.c: Checking device state for peer 01xxxxxx201
[Jul 2 10:16:26] DEBUG[29067] devicestate.c: Changing state for SIP/01xxxxxx201 - state 1 (Not in use)
[Jul 2 10:16:26] DEBUG[17856] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jul 2 10:16:26] DEBUG[17856] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2007-07-02 10:16:20’,’“HP 7940” <101>’,‘101’,‘07xxxxx5666’,‘from-internal’, ‘SIP/101-b7c0d358’,‘SIP/01xxxxxx201-088cd5a8’,‘Dial’,‘SIP/01xxxxxx201/07xxxxx5666|300|TtW’,6,0,‘NO ANSWER’,3,’’)
[Jul 2 10:16:26] DEBUG[17856] app_macro.c: Executed application: ResetCDR
[Jul 2 10:16:26] DEBUG[17856] pbx.c: Launching ‘NoCDR’[/size]

Any ideas?

Thanks,
C.

This is due to work being done on the CDR module by murf. There are multiple posts about this on this forum(last week by murf) and on lists.digium.com, and a ‘patch’/fix on bugs.digium.com. I’m sorry, I dont have exact URL’s on hand.

Thanks yusuf. I’ll try to track the patch down. I just installed 1.4.6 and the ‘problem’ is still in that.

C.

I searched through the mailing lists and the bug database and I see what’s being discussed but I guess I’m still confused. Being pretty new to all this I guess I don’t want to go wading in with my size 10s before I really know what I’m talking about.

I guess my question is whether what I am seeing is expected behaviour for Asterisk 1.4.6/FreePBX, i.e. irrelevant (at least in my case) call detail records which seem to also confuse/break ARI.

I don’t need to log, for example, 101 calling 102 if 101 abandoned the call. Nor do I need to see every single extension that was called (but did not answer) as part of a ring-group - especially when dst is shown as ‘s’.

What am I missing here? Where would a novice like me be best posting this question without bothering the author of the changes (I guess ‘murf’).

Thanks in advance and sorry for the ramble.

Chris.

It is expected behaviour, i.e. not a misconfigured .conf file or not a bug(mainly). Well, you can use that patch/fix to get rid of the ‘s’ entries. Or just wait a bit, maybe not just a bit :smile:, until 1.6 comes out, and CDR’s will be alot more powerfull.

I found the URL for the bug report, but can not find the patch attached. Where did you see the patch and what did it actually fix?

bugs.digium.com/view.php?id=10067

Thank you so much yusuf. This is all I needed to know :smile:.

[quote=“tracinet”]I found the URL for the bug report, but can not find the patch attached. Where did you see the patch and what did it actually fix?

bugs.digium.com/view.php?id=10067[/quote]

Tracinet, thank you also. I think I did happen upon this and sometimes woods and trees just get the better me. I think the patch-diff was in an email thread on one of the mailing lists.

For now I’ll live with it and just delete out those records I don’t need - the main thing is that it’s not my config - so I’m happy :smile:

Thanks again all.