DTMF Erkennung

17 Aug 2006

      Hallo,

ich beabsichtige das Anrufbeantwortersystem VOCP mit Hilfe von vgetty und 
einer Fritz ISDN PCI 2.0 zu betreiben.
Habe SuSE 10.1 mit i4l / capi4linux 2006.4.25-4 und capisuite 0.4.5-19 sowie 
die Capi Treiber von http://opensuse.fltronic.de/ für den Kernel 2.6.16-21.

Fogendes Problem: Nach Annahme des Anrufs und eingehender DTMF-Töne reagiert 
VOCP nicht. Habe hier mal den vgetty-log:

08/17 20:27:00 yI7    Linux ISDN: OK
08/17 20:27:00 yI7   voice command: 'AT+FCLASS=8' -> 'OK'
08/17 20:27:00 yI7    vgetty: AT+FCLASS=8
08/17 20:27:00 yI7    Linux ISDN: OK
08/17 20:27:00 yI7   voice command: 'AT' -> 'OK'
08/17 20:27:00 yI7    vgetty: AT
08/17 20:27:00 yI7    Linux ISDN: OK
08/17 20:27:00 yI7    vgetty: queued event RESET_WATCHDOG at position 0001
08/17 20:27:00 yI7   voice command: 'ATS20?' -> '0|1|2|3|4'
08/17 20:27:01 yI7    vgetty: ATS20?
08/17 20:27:01 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0001
08/17 20:27:01 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <_>
08/17 20:27:01 yI7    Linux ISDN: 1
08/17 20:27:01 yI7   voice command: 'ATA' -> 'VCON'
08/17 20:27:01 yI7    vgetty: ATA
08/17 20:27:01 yI7    Linux ISDN: OK
08/17 20:27:01 yI7    Linux ISDN: VCON
08/17 20:27:01 yI7    vgetty: queued event RESET_WATCHDOG at position 0002
08/17 20:27:01 yI7   voice command: 'AT+VLS=2' -> 'VCON|OK|NO CARRIER'
08/17 20:27:01 yI7    vgetty: AT+VLS=2
08/17 20:27:01 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0002
08/17 20:27:01 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <_>
08/17 20:27:01 yI7    Linux ISDN: OK
08/17 20:27:01 yI7  vgetty: Executing shell script /usr/local/vocp/bin/vocp.pl 
with shell /usr/bin/perl
08/17 20:27:01 yI7    vgetty: opening pipes
08/17 20:27:01 yI7    vgetty: forking shell
08/17 20:27:01 yI7   vgetty(0): HELLO SHELL
08/17 20:27:01 yI7    vgetty: Got pipe signal
08/17 20:27:01 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0003
08/17 20:27:01 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0003
08/17 20:27:01 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:01 yI7   shell(1): HELLO VOICE PROGRAM
08/17 20:27:01 yI7   vgetty(1): READY
08/17 20:27:01 yI7   vgetty: initialized communication
08/17 20:27:01 yI7    vgetty: Got pipe signal
08/17 20:27:01 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0004
08/17 20:27:01 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0004
08/17 20:27:01 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:01 yI7   shell(1): DEVICE DIALUP_LINE
08/17 20:27:01 yI7    vgetty: queued event RESET_WATCHDOG at position 0005
08/17 20:27:01 yI7   voice command: 'AT+VLS=2' -> 'VCON|OK|NO CARRIER'
08/17 20:27:01 yI7    vgetty: AT+VLS=2
08/17 20:27:01 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0005
08/17 20:27:01 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <x>
08/17 20:27:01 yI7    Linux ISDN: OK
08/17 20:27:01 yI7   vgetty(1): READY
08/17 20:27:01 yI7    vgetty: Got pipe signal
08/17 20:27:01 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0006
08/17 20:27:01 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0006
08/17 20:27:01 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:01 yI7   shell(1): AUTOSTOP ON
08/17 20:27:01 yI7   vgetty(1): READY
08/17 20:27:02 yI7    vgetty: Got pipe signal
08/17 20:27:02 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0007
08/17 20:27:02 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0007
08/17 20:27:02 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:02 yI7   shell(1): ENABLE EVENTS
08/17 20:27:02 yI7   vgetty(1): READY
08/17 20:27:02 yI7    vgetty: Got pipe signal
08/17 20:27:02 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0008
08/17 20:27:02 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0008
08/17 20:27:02 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:02 yI7   shell(1): PLAY /var/spool/voice/messages/root.rmd
08/17 20:27:02 yI7   vgetty(1): PLAYING
08/17 20:27:02 yI7  playing voice file /var/spool/voice/messages/root.rmd
08/17 20:27:02 yI7   vgetty: raw modem data header found
08/17 20:27:02 yI7   vgetty: modem type ISDN4Linux found
08/17 20:27:02 yI7   vgetty: compression method 0x0006, speed 8000, bits 8
08/17 20:27:02 yI7    vgetty: queued event RESET_WATCHDOG at position 0009
08/17 20:27:02 yI7   voice command: 'AT+VSM=6' -> 'OK'
08/17 20:27:02 yI7    vgetty: AT+VSM=6
08/17 20:27:02 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0009
08/17 20:27:02 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <x>
08/17 20:27:02 yI7    Linux ISDN: OK
08/17 20:27:02 yI7    vgetty: queued event RESET_WATCHDOG at position 0010
08/17 20:27:02 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0010
08/17 20:27:02 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <x>
08/17 20:27:02 yI7   voice command: 'AT' -> 'OK'
08/17 20:27:02 yI7    vgetty: AT
08/17 20:27:02 yI7    Linux ISDN: OK
08/17 20:27:02 yI7   tio_set_flow_control( HARD XON_OUT )
08/17 20:27:02 yI7   voice command: 'AT+VTX' -> 'CONNECT|NO ANSWER'
08/17 20:27:02 yI7    vgetty: AT+VTX
08/17 20:27:02 yI7    Linux ISDN: CONNECT
08/17 20:27:03 yI7    Linux ISDN: <DLE> <_>
08/17 20:27:03 yI7  vgetty: Unknown code <DLE> <_>
08/17 20:27:04 yI7    Linux ISDN: <DLE> <_>
08/17 20:27:04 yI7  vgetty: Unknown code <DLE> <_>
08/17 20:27:05 yI7    vgetty: 
08/17 20:27:05 yI7    vgetty: queued event RESET_WATCHDOG at position 0011
08/17 20:27:05 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0011
08/17 20:27:05 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <x>
08/17 20:27:05 yI7    vgetty: <STOP PLAY>
08/17 20:27:05 yI7   voice command: '' -> 'OK|VCON'
08/17 20:27:05 yI7    Linux ISDN: VCON
08/17 20:27:05 yI7   vgetty(1): READY
08/17 20:27:05 yI7    vgetty: Got pipe signal
08/17 20:27:05 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0012
08/17 20:27:05 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0012
08/17 20:27:05 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:05 yI7   shell(1): WAIT 3
08/17 20:27:05 yI7   vgetty(1): WAITING
08/17 20:27:05 yI7    vgetty: queued event RESET_WATCHDOG at position 0013
08/17 20:27:05 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0013
08/17 20:27:05 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <_>
08/17 20:27:05 yI7    vgetty: queued event RESET_WATCHDOG at position 0014
08/17 20:27:05 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0014
08/17 20:27:05 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <_>
08/17 20:27:09 yI7   vgetty(1): READY
08/17 20:27:09 yI7    vgetty: Got pipe signal
08/17 20:27:09 yI7    vgetty: queued event SIGNAL_SIGPIPE at position 0015
08/17 20:27:09 yI7    vgetty: unqueued event SIGNAL_SIGPIPE at position 0015
08/17 20:27:09 yI7    vgetty: voice_handle_event got event SIGNAL_SIGPIPE with 
data <_>
08/17 20:27:09 yI7   shell(1): PLAY /var/spool/voice/messages/system/error.rmd
08/17 20:27:09 yI7   vgetty(1): PLAYING
08/17 20:27:09 yI7  playing voice 
file /var/spool/voice/messages/system/error.rmd
08/17 20:27:09 yI7   vgetty: raw modem data header found
08/17 20:27:09 yI7   vgetty: modem type ISDN4Linux found
08/17 20:27:09 yI7   vgetty: compression method 0x0006, speed 8000, bits 8
08/17 20:27:09 yI7    vgetty: queued event RESET_WATCHDOG at position 0016
08/17 20:27:09 yI7   voice command: 'AT+VSM=6' -> 'OK'
08/17 20:27:09 yI7    vgetty: AT+VSM=6
08/17 20:27:09 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0016
08/17 20:27:09 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <_>
08/17 20:27:09 yI7    Linux ISDN: OK
08/17 20:27:09 yI7    vgetty: queued event RESET_WATCHDOG at position 0017
08/17 20:27:09 yI7    vgetty: unqueued event RESET_WATCHDOG at position 0017
08/17 20:27:09 yI7    vgetty: voice_handle_event got event RESET_WATCHDOG with 
data <_>
08/17 20:27:09 yI7   voice command: 'AT' -> 'OK'
08/17 20:27:09 yI7    vgetty: AT
08/17 20:27:09 yI7    Linux ISDN: OK
08/17 20:27:09 yI7   tio_set_flow_control( HARD XON_OUT )
08/17 20:27:09 yI7   voice command: 'AT+VTX' -> 'CONNECT|NO ANSWER'
08/17 20:27:09 yI7    vgetty: AT+VTX
08/17 20:27:09 yI7    Linux ISDN: CONNECT
08/17 20:27:09 yI7    Linux ISDN: <DLE> <_>
08/17 20:27:09 yI7  vgetty: Unknown code <DLE> <_>
08/17 20:27:09 yI7    Linux ISDN: <DLE> <_>
08/17 20:27:09 yI7  vgetty: Unknown code <DLE> <_>
08/17 20:27:09 yI7    vgetty: 

Die Zeilen "Linux ISDN: <DLE> <_>" sind das eigentliche Problem, da müssten 
eigentlich die Ziffern der gedrückten Tasten auftauchen. Da vgetty also nur 
"Unkonw code <DLE> <_>" bekommt, kann VOCP natürlich auch auf nichts 
reagieren.
Allerdings zeigt "tail -f /var/log/messages | grep dtmf"  folgendes:

Aug 17 20:27:03 r2d2 kernel: dtmf: tt='1'
Aug 17 20:27:04 r2d2 kernel: dtmf: tt='2'
Aug 17 20:27:09 r2d2 kernel: dtmf: tt='3'
Aug 17 20:27:09 r2d2 kernel: dtmf: tt='4'

Also genau die Zifferntasten, die ich gedrückt habe. 

Ein kurz aufgerufener vboxgetty zeigte beim Empfang von DTMF-Sequenzen 
folgendes:
17-Aug 13:14:28 <E> Illeagal "<DLE>" shielded code "[0xFF]" (ignored)...

Habe dann das Terminalprogramm "minicom" gestartet und folgende AT-Sequenzen 
im Dialog für das ISDN-Device eingegeben:

AT S7=45 S0=0 L1 V1 &c1 E1 Q0
OK
atz
OK
at&b512
OK
at&eXXXXXX
OK
at+fclass=8
OK
ats18=5
OK
ats13=20
OK
at+vls=2
OK

RING
CALLER NUMBER: XXXXXXXX
ata
VCON
at+vls=2
OK
at+vls=0
OK
at+vls=2
OK
at+vsm=6
OK
at+vtx
CONNECT
....
NO CARRIER

Die zweitletzte Zeile zeigt eben auch nur je einen Punkt pro ankommenden 
DTMF-Ton, das sollte eigentlich so aussehen:
.1.2.3.4
/var/log/messages zeigte es wieder korrekt.

Ich weiß an dieser Stelle nicht mehr weiter, welches Programm sorgt für die 
DTMF-Erkennung bzw. Weiterleitung vom Kernel?
Muss noch irgendein Register über den AT-Befehlssatz geändert werden?
Wo finde ich die komplette AT-Befehlssatz-Beschreibung für i4l?
Oder ist das ganze ein Bug?

Um jede Hilfe wäre ich sehr dankbar.

Übrigens: Auf einem anderen System mit SuSE 9.2 und Kernel 2.6.11 sowie einer 
alten Fritz ISDN PCI funktioniert das ganze mit den o.g. Befehlssequenzen 
problemlos.

Klaus Nitsche