[Home]

Summary:ASTERISK-16626: DTMF not logged to console when configured in logger.conf
Reporter:Jeremy Kister (jkister)Labels:
Date Opened:2010-08-27 21:57:37Date Closed:2011-06-08 14:16:47
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) IMG_0003.mpg
( 1) sip.txt
Description:duplicate issue of 0017043, except I am using the latest version of the 1.6.2 line of Asterisk compiled from source.

DTMF works correctly; I can see the packets when I tcpdump.  I just never see any DTMF related information on the console.


pbx1> grep -i dtmf /etc/asterisk/logger.conf
;    dtmf
console => notice,warning,error,dtmf
pbx1> suex /etc/init.d/asterisk stop
pbx1> ps -ef | grep asterisk
jkister   2359  1598  0 22:50 pts/2    00:00:00 grep asterisk
pbx1> suex /etc/init.d/asterisk start
pbx1> suex asterisk -r
Asterisk 1.6.2.11, Copyright (C) 1999 - 2010 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
Connected to Asterisk 1.6.2.11 currently running on pbx1 (pid = 2272)
Verbosity is at least 3
pbx1*CLI> core set debug 5
Core debug was 0 and is now 5
pbx1*CLI> core set verbose 5
Verbosity was 3 and is now 5
pbx1*CLI> logger show channels
Channel                             Type     Status    Configuration
-------                             ----     ------    -------------
/var/log/asterisk/messages          File     Enabled    - Warning Notice Error
                                   Console  Enabled    - DTMF Warning Notice Error
pbx1*CLI>
pbx1*CLI>
 == Using SIP RTP CoS mark 5
 == Using SIP VRTP CoS mark 6
 == Using UDPTL CoS mark 5
   -- Executing [8008374966@extensions:1] Set("SIP/101-00000006", "CALLERID(all)=The Kisters <0005551212>") in new stack
   -- Executing [8008374966@extensions:2] Macro("SIP/101-00000006", "SaferSIPDial,8008374966") in new stack
   -- Executing [s@macro-SaferSIPDial:1] Set("SIP/101-00000006", "DIALTRIES=1") in new stack
   -- Executing [s@macro-SaferSIPDial:2] GotoIf("SIP/101-00000006", "0?unavail") in new stack
   -- Executing [s@macro-SaferSIPDial:3] Set("SIP/101-00000006", "SIPSERVER=vgw1") in new stack
   -- Executing [s@macro-SaferSIPDial:4] GotoIf("SIP/101-00000006", "1?preroute") in new stack
   -- Goto (macro-SaferSIPDial,s,10)
   -- Executing [s@macro-SaferSIPDial:10] Set("SIP/101-00000006", "PREROUTE=9930") in new stack
   -- Executing [s@macro-SaferSIPDial:11] GotoIf("SIP/101-00000006", "1?dial") in new stack
   -- Goto (macro-SaferSIPDial,s,15)
   -- Executing [s@macro-SaferSIPDial:15] NoOp("SIP/101-00000006", ""Dialing SIP/99308008374966@vgw1 - try 1"") in new stack
   -- Executing [s@macro-SaferSIPDial:16] Dial("SIP/101-00000006", "SIP/99308008374966@vgw1") in new stack
 == Using SIP RTP CoS mark 5
 == Using SIP VRTP CoS mark 6
 == Using UDPTL CoS mark 5
   -- Called 99308008374966@vgw1
   -- SIP/vgw1-00000007 is making progress passing it to SIP/101-00000006
   -- SIP/vgw1-00000007 answered SIP/101-00000006
 == Spawn extension (macro-SaferSIPDial, s, 16) exited non-zero on 'SIP/101-00000006' in macro 'SaferSIPDial'
 == Spawn extension (extensions, 8008374966, 2) exited non-zero on 'SIP/101-00000006'
pbx1*CLI>

I entered lots of DTMF going through Verizon's Automated Attendant Hell.  The DTMF was received by verizon just fine but nothing DTMF related logged to my console



****** ADDITIONAL INFORMATION ******

I'm happy to give an Asterisk admin/coder ssh access to the box as well as configure a remote sip client for debugging.
Comments:By: Russell Bryant (russell) 2010-09-09 15:52:33

Can you attach a packet capture?  Are you _sure_ the DTMF is going through Asterisk?  You're only going to see the DTMF log entries if Asterisk processes the DTMF.  Based on the information we have so far, it's likely that the media stream (including the DTMF) was directed away from Asterisk using a re-INVITE.

By: Brian J. Murrell (brian_j_murrell) 2010-09-10 13:52:37

A packet capture will be attached.  I filtered out the regular PCMU RTP for brevity and privacy.  "pbx" is the Asterisk server.  While I was hitting 12345 on my phone I saw nothing on the console.  The other end (the "5551212" party) responded to the DTMF so I know it went end-to-end and the packet trace clearly shows it being sent to the Asterisk server.

By: Leif Madsen (lmadsen) 2010-09-16 09:30:55

Can you define what each IP address represents? (Asterisk, phone, far-end, etc...)

Also, I think it would be useful to see the contents of your logger.conf along with the console output of 'logger show channels' from the Asterisk console.

By: Brian J. Murrell (brian_j_murrell) 2010-09-16 10:38:38

10.75.22.198 is an ATA
10.75.22.8 is the Asterisk server, a.k.a. "pbx"

logger.conf (sed simply strips comments and vertical whitespace):

# sed -e 's/;.*//' -e '/^$/d' /etc/asterisk/logger.conf
[general]
dateformat=%F %T      
[logfiles]
console => notice,warning,error,dtmf
messages => notice,warning,error


linux*CLI> logger show channels
Channel                     Type     Status  Configuration
-------                     ----     ------  -------------
/var/log/asterisk/messages  File     Enabled  - Warning Notice Error
                           Console  Enabled  - DTMF Warning Notice Error

By: Jeremy Kister (jkister) 2010-11-14 00:29:04.000-0600

same behavior confirmed running Asterisk 1.8.0

By: Vladimir Mikhelson (vmikhelson) 2010-11-29 23:09:45.000-0600

Same with 1.6.2.14

By: Vladimir Mikhelson (vmikhelson) 2010-11-29 23:19:27.000-0600

Re-tested. DTMF logging to the file works fine in 1.6.2.14.

By: Brian J. Murrell (brian_j_murrell) 2010-12-21 06:57:16.000-0600

I am using 1.6.2.15 now and I still don't have display of DTMF debugging in the console.

By: Jeremy Kister (jkister) 2011-01-10 22:13:43.000-0600

Now on 1.8.1.1

i added "dtmf" to the "messages" section:
pbx1> grep dtmf logger.conf
;    dtmf
console => notice,warning,error,dtmf
messages => notice,warning,error,dtmf

and i can confirm that I do get DTMF messages in the log file, but still not on the console:
[Jan 10 23:11:50] DTMF[27061] channel.c: DTMF begin '2' received on SIP/111-000003ef
[Jan 10 23:11:50] DTMF[27061] channel.c: DTMF begin passthrough '2' on SIP/111-000003ef
[Jan 10 23:11:50] DTMF[27061] channel.c: DTMF end '2' received on SIP/111-000003ef, duration 200 ms
[Jan 10 23:11:50] DTMF[27061] channel.c: DTMF end accepted with begin '2' on SIP/111-000003ef
[Jan 10 23:11:50] DTMF[27061] channel.c: DTMF end passthrough '2' on SIP/111-000003ef

By: Ronald Chan (loloski) 2011-01-11 12:12:58.000-0600

i second to this, i'm trying to triage a dtmf issues a while ago on my home installation and i found out that this is the case, on /var/log/asterisk/message the dtmf is there, while in console it doesn't log anything.

By: Luke H (luckman212) 2011-05-12 22:53:45

what I noticed was there seems to be something "reversed" for lack of a better word.

when I enable DTMF logging via logger.conf, it DOES log them to /var/log/asterisk/full but NOT to the console

UNTIL...

I type 'logger set level DTMF off'
then I start to see them.
shouldn't that be 'logger set level DTMF on' ???

By: Vladimir Mikhelson (vmikhelson) 2011-05-13 00:33:46

Wow!! Great discovery.

The problem is solved. At least for practical purposes.

Works like a charm.  Does not affect DTMF logging to a file.

Thank you,
Vladimir

By: Brian J. Murrell (brian_j_murrell) 2011-05-13 09:33:13

Well, the problem is not "solved".  Some data has been gathered that should help pinpoint the actual problem such that a solution can be landed to the 1.6.2 branch.  Until that solution is landed, this problem is not "solved".

I should add however, that this is indeed a great discovery.



By: Vladimir Mikhelson (vmikhelson) 2011-05-13 23:32:29

It looks like it is fixed in 1.8.4.

Console DTMF logging works as expected.  File DTMF logging is not broken either.

Thanks to whoever fixed it!  I do not know whether it was back-ported to 1.6.2.x.

Vladimir

By: Luke H (luckman212) 2011-05-16 21:53:37

are you sure this is fixed in 1.8.4?  It wasn't for me.   I've even updated to SVN-branch-1.8-r319261M  and still having this issue...

By: Vladimir Mikhelson (vmikhelson) 2011-05-16 23:03:54

I have just verified, it works. Contents of /var/log/asterisk/dtmf and the console output are identical with DTMF highlighted in green. Tested with SIP and DAHDI.

Asterisk 1.8.4 built by root...

logger.conf
dtmf => dtmf
console => dtmf

-Vladimir



By: Jeremy Kister (jkister) 2011-05-16 23:07:45

not everyone was experiencing the original issue.  it's possible that 1.8.4 fixed something for some people; it's possible that the issue still exists for others.

By: Vladimir Mikhelson (vmikhelson) 2011-05-16 23:20:14

What do you think differentiates the "original" issue?

I observed DTMF stopped being produced in the console output after one of the Asterisk updates. File log was still working fine.

First, 'logger set level DTMF off' helped.  Then next day I installed 1.8.4 and did not need to use the 'logger set...' any more.

Just my experience.

-Vladimir

By: Jeremy Kister (jkister) 2011-05-16 23:50:45

oh i don't know.  I'm just acknowledging that this issue is so strange that I believe your issue is fixed and i believe @luckman212's is still broken.

By: Luke H (luckman212) 2011-05-30 10:15:27

vmikhelson:   are you still sure that the issue does not exist for you anymore?  Even after a full shutdown & restart of asterisk? I've tried to duplicate your logger.conf and (at least on my system) I am still seeing this issue.

By: Vladimir Mikhelson (vmikhelson) 2011-05-30 18:19:49

luckman212: I am positive as I could be as it works as expected now.

I did restart Asterisk multiple times, and it did not break the DTMF console logging for me.  I have not rebooted the box ever since 05/07 though.

One thought. I am not seeing DTMF in any SSH sessions, I do not believe I ever did. I do see DTMF logging in the real console after 1.8.4 was installed.

-Vladimir

By: Luke H (luckman212) 2011-05-30 22:26:40

Hmm.  I didn't know there was any difference between running 'asterisk -r' from a local console vs. an SSH session.  This is news to me.  And I do see the DTMF logged via SSH but only after issuing 'logger set level dtmf OFF'

By: Vladimir Mikhelson (vmikhelson) 2011-05-31 18:38:41

As I said, I never observed DTMF logging active in SSH sessions and kind of assumed it was by design.

I have verified the 'logger set level dtmf OFF' turns DTMF logging on in a SSH session, and 'logger set level dtmf ON' turns it off.

As we are on this topic. There are other circumstances when an output is only visible on the local console. Take a look here for an example: https://issues.asterisk.org/view.php?id=18847

-Vladimir

By: Jeremy Kister (jkister) 2011-06-08 14:16:02.271-0500


A new issue was opened by Luke H and resolved the problem.

https://issues.asterisk.org/view.php?id=19287

https://issues.asterisk.org/jira/browse/ASTERISK-17850


By: Jeremy Kister (jkister) 2011-06-08 14:16:47.445-0500

https://issues.asterisk.org/jira/browse/ASTERISK-17850