thanks for that hint - i will recompile asterisk with the fix later.
nevertheless everything seems to work - i don't use too much functions anyway.
But fax is still not working...
edit: just tried it from an analgoue fax-device to my asterisk - it doesn't work as well. i can hear the initial beep of the sending fax, but asterisk doesn't reacts. the error message is the same:
[Oct 20 08:48:03] -- Channel 'SIP/2636146-00000033' receiving FAX '/opt/tmp/fax-1319100483.51.tif'
[Oct 20 08:48:06] WARNING[25260]: chan_sip.c:19673 handle_response_invite: Received response: "Forbidden" from '<sip:<callerid(dnid)>@<ip>:56005>;tag=as00c4bf65'
Code: Alles auswählen
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Oct 20 14:07:00] DEBUG[25260] netsock2.c: Splitting '192.168.1.1:56005' into...
[Oct 20 14:07:00] DEBUG[25260] netsock2.c: ...host '192.168.1.1' and port '56005'.
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x6f8058'
[Oct 20 14:07:00] DEBUG[25260] res_rtp_asterisk.c: Allocated port 24772 for RTP instance '0x6f8058'
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: RTP instance '0x6f8058' is setup and ready to go
[Oct 20 14:07:00] DEBUG[25260] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x6f8058'
[Oct 20 14:07:00] VERBOSE[25260] netsock2.c: [Oct 20 14:07:00] == Using SIP RTP CoS mark 5
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Setting NAT on RTP to Off
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Setting NAT on UDPTL to Off
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing session-level SDP o=hiQ9200 6264620110920160700 1830944805 IN IP4 192.168.1.1... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing session-level SDP s=Phone Call via hiQ9200 SIPCA... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] netsock2.c: Splitting '192.168.1.1' into...
[Oct 20 14:07:00] DEBUG[25260] netsock2.c: ...host '192.168.1.1' and port ''.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.1.1... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Setting payload 8 based on m type on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Setting payload 0 based on m type on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Setting payload 18 based on m type on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=fmtp:8 vad=no... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=fmtp:0 vad=no... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-32/8000... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 vad=no... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=fmtp:2 vad=no... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:100 telephone-event/8000... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=fmtp:100 0-15... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=sqn: 0... UNSUPPORTED.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK.
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Incorporating payload 0 on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Incorporating payload 2 on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Incorporating payload 8 on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Incorporating payload 18 on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Incorporating payload 96 on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Incorporating payload 100 on 0x7dffbb60
[Oct 20 14:07:00] DEBUG[25260] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x6f8058'
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Copying payload 0 from 0x7dffbb60 to 0x6f8208
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Copying payload 2 from 0x7dffbb60 to 0x6f8208
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Copying payload 8 from 0x7dffbb60 to 0x6f8208
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Copying payload 18 from 0x7dffbb60 to 0x6f8208
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Copying payload 96 from 0x7dffbb60 to 0x6f8208
[Oct 20 14:07:00] DEBUG[25260] rtp_engine.c: Copying payload 100 from 0x7dffbb60 to 0x6f8208
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: We're settling with these formats: 0x80c (ulaw|alaw|g726)
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Checking SIP call limits for device
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Updating call counter for incoming call
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: *** Our native formats are 0x8 (alaw)
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: *** Joint capabilities are 0x80c (ulaw|alaw|g726)
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: *** Our capabilities are 0x180e (gsm|ulaw|alaw|g726|g722)
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: This channel will not be able to handle video.
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: build_route: Record-Route hop: <sip:siproxd@192.168.1.1:56005;lr>
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: build_route: Record-Route hop: <sip:DTMTASP01-forward@217.0.17.154:5060;lr>
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: build_route: Record-Route hop: <sip:DTMTASP01-forward@62.155.3.66:5060;transport=udp;lr>
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: SIP/tel.t-online.de-00000059: New call is still down.... Trying...
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.1.1:56005
[Oct 20 14:07:00] DEBUG[25253] devicestate.c: No provider found, checking channel drivers for SIP - tel.t-online.de
[Oct 20 14:07:00] DEBUG[25253] chan_sip.c: Checking device state for peer tel.t-online.de
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Function result is '+498912345678'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'Set'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [02345123456@default:1] Set("SIP/tel.t-online.de-00000059", "CALLERID(num)=+498912345678") in new stack
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Function result is '+498912345678'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Function result is '02345123456'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'Log'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [02345123456@default:2] Log("SIP/tel.t-online.de-00000059", "NOTICE, "Default-Start: Eingehender Anruf von +498912345678 an 02345123456"") in new stack
[Oct 20 14:07:00] NOTICE[32452] Ext. 02345123456: "Default-Start: Eingehender Anruf von +498912345678 an 02345123456"
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Function result is '02345123456'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'Set'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [02345123456@default:3] Set("SIP/tel.t-online.de-00000059", "MSN=02345123456") in new stack
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Result of 'MSN' is '02345123456'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Expression result is '0'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'GosubIf'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [02345123456@default:4] GosubIf("SIP/tel.t-online.de-00000059", "0?DNID_subs,sub123457,1:") in new stack
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Result of 'MSN' is '02345123456'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Expression result is '11'
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'GosubIf'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [02345123456@default:5] GosubIf("SIP/tel.t-online.de-00000059", "11?DNID_subs,sub123456,1:") in new stack
[Oct 20 14:07:00] DEBUG[32452] app_stack.c: Channel SIP/tel.t-online.de-00000059 has no datastore, so we're allocating one.
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'Answer'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [sub123456@DNID_subs:1] Answer("SIP/tel.t-online.de-00000059", "") in new stack
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: SIP answering channel: SIP/tel.t-online.de-00000059
[Oct 20 14:07:00] DEBUG[32452] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: Setting framing from config on incoming call
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: ** Our capability: 0x80c (ulaw|alaw|g726) Video flag: True Text flag: True
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: -- Done with adding codecs to SDP
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: Done building SDP. Settling with this capability: 0x80c (ulaw|alaw|g726)
[Oct 20 14:07:00] DEBUG[32452] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.1:56005
[Oct 20 14:07:00] DEBUG[25253] devicestate.c: Changing state for SIP/tel.t-online.de - state 2 (In use)
[Oct 20 14:07:00] DEBUG[25253] devicestate.c: device 'SIP/tel.t-online.de' state '2'
[Oct 20 14:07:00] DEBUG[25253] devicestate.c: No provider found, checking channel drivers for SIP - tel.t-online.de
[Oct 20 14:07:00] DEBUG[25253] chan_sip.c: Checking device state for peer tel.t-online.de
[Oct 20 14:07:00] DEBUG[25253] devicestate.c: Changing state for SIP/tel.t-online.de - state 2 (In use)
[Oct 20 14:07:00] DEBUG[25253] devicestate.c: device 'SIP/tel.t-online.de' state '2'
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: = Looking for Call ID: 0a8fa6020304a428@62.155.0.194 (Checking From) --From tag 3d9f9d92 --To-tag as7dce4d5d
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Oct 20 14:07:00] DEBUG[25260] chan_sip.c: Stopping retransmission on '0a8fa6020304a428@62.155.0.194' of Response 19387098: Match Found
[Oct 20 14:07:00] DEBUG[32452] pbx.c: Launching 'Wait'
[Oct 20 14:07:00] VERBOSE[32452] pbx.c: [Oct 20 14:07:00] -- Executing [sub123456@DNID_subs:2] Wait("SIP/tel.t-online.de-00000059", "2") in new stack
[Oct 20 14:07:02] DEBUG[32452] pbx.c: Function result is '1319119620.89'
[Oct 20 14:07:02] DEBUG[32452] pbx.c: Launching 'Set'
[Oct 20 14:07:02] VERBOSE[32452] pbx.c: [Oct 20 14:07:02] -- Executing [sub123456@DNID_subs:3] Set("SIP/tel.t-online.de-00000059", "FAXFILE=/opt/root/fax1319119620.89.tif") in new stack
[Oct 20 14:07:02] DEBUG[32452] pbx.c: Result of 'FAXFILE' is '/opt/root/fax1319119620.89.tif'
[Oct 20 14:07:02] DEBUG[32452] pbx.c: Launching 'ReceiveFAX'
[Oct 20 14:07:02] VERBOSE[32452] pbx.c: [Oct 20 14:07:02] -- Executing [sub123456@DNID_subs:4] ReceiveFAX("SIP/tel.t-online.de-00000059", "/opt/root/fax1319119620.89.tif") in new stack
[Oct 20 14:07:02] VERBOSE[32452] res_fax.c: [Oct 20 14:07:02] -- Channel 'SIP/tel.t-online.de-00000059' receiving FAX '/opt/root/fax1319119620.89.tif'
[Oct 20 14:07:02] DEBUG[32452] res_fax.c: Reserving a FAX session from 'Spandsp FAX Driver'.
[Oct 20 14:07:02] DEBUG[32452] res_fax.c: Selected FAX technology module (Spandsp FAX Driver) does not support reserving sessions.
[Oct 20 14:07:02] DEBUG[32452] channel.c: Set channel SIP/tel.t-online.de-00000059 to write format slin
[Oct 20 14:07:02] DEBUG[32452] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw
[Oct 20 14:07:02] DEBUG[32452] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160
[Oct 20 14:07:03] DEBUG[32452] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Oct 20 14:07:05] DEBUG[32452] channel.c: Auto-deactivating generator
[Oct 20 14:07:05] DEBUG[32452] channel.c: Set channel SIP/tel.t-online.de-00000059 to write format alaw
[Oct 20 14:07:05] DEBUG[32452] res_fax.c: Negotiating T.38 for receive on SIP/tel.t-online.de-00000059
[Oct 20 14:07:05] DEBUG[32452] chan_sip.c: T38 state changed to 1 on channel SIP/tel.t-online.de-00000059
[Oct 20 14:07:05] DEBUG[32452] netsock2.c: Splitting '192.168.1.1:56005' into...
[Oct 20 14:07:05] DEBUG[32452] netsock2.c: ...host '192.168.1.1' and port '56005'.
[Oct 20 14:07:05] DEBUG[32452] chan_sip.c: Done building SDP. Settling with this capability: 0x0 (nothing)
[Oct 20 14:07:05] DEBUG[32452] chan_sip.c: Initializing already initialized SIP dialog 0a8fa6020304a428@62.155.0.194 (presumably reinvite)
[Oct 20 14:07:05] DEBUG[32452] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.1.1:56005
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: = Looking for Call ID: 0a8fa6020304a428@62.155.0.194 (Checking To) --From tag as7dce4d5d --To-tag 3d9f9d92
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '0a8fa6020304a428@62.155.0.194' Request 102: Found
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: SIP response 100 to RE-invite on outgoing call 0a8fa6020304a428@62.155.0.194
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: = Looking for Call ID: 0a8fa6020304a428@62.155.0.194 (Checking To) --From tag as7dce4d5d --To-tag 3d9f9d92
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: Acked pending invite 102
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: Stopping retransmission on '0a8fa6020304a428@62.155.0.194' of Request 102: Match Found
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: SIP response 403 to RE-invite on outgoing call 0a8fa6020304a428@62.155.0.194
[Oct 20 14:07:05] DEBUG[25260] netsock2.c: Splitting '192.168.1.1:56005' into...
[Oct 20 14:07:05] DEBUG[25260] netsock2.c: ...host '192.168.1.1' and port '56005'.
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: Trying to put 'ACK sip:TAS' onto UDP socket destined for 192.168.1.1:56005
[Oct 20 14:07:05] WARNING[25260] chan_sip.c: Received response: "Forbidden" from '<sip:02345123456@79.253.179.39:56005>;tag=as7dce4d5d'
[Oct 20 14:07:05] DEBUG[25260] chan_sip.c: Setting SIP_ALREADYGONE on dialog 0a8fa6020304a428@62.155.0.194
[Oct 20 14:07:10] DEBUG[25260] chan_sip.c: = Looking for Call ID: 0a8fa6020304a428@62.155.0.194 (Checking From) --From tag 3d9f9d92 --To-tag as7dce4d5d
[Oct 20 14:07:10] DEBUG[25260] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Oct 20 14:07:10] DEBUG[25260] netsock2.c: Splitting '192.168.1.1:56005' into...
[Oct 20 14:07:10] DEBUG[25260] netsock2.c: ...host '192.168.1.1' and port '56005'.
[Oct 20 14:07:10] DEBUG[25260] chan_sip.c: Setting SIP_ALREADYGONE on dialog 0a8fa6020304a428@62.155.0.194
[Oct 20 14:07:10] DEBUG[25260] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x6f8058'
[Oct 20 14:07:10] DEBUG[25260] chan_sip.c: Received bye, issuing owner hangup
[Oct 20 14:07:10] DEBUG[25260] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.1.1:56005
[Oct 20 14:07:10] WARNING[32452] res_fax.c: error on 'SIP/tel.t-online.de-00000059' while waiting for T.38 negotiation.
[Oct 20 14:07:10] ERROR[32452] res_fax.c: error initializing channel 'SIP/tel.t-online.de-00000059' in T.38 mode
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Spawn extension (DNID_subs,sub123456,4) exited non-zero on 'SIP/tel.t-online.de-00000059'
[Oct 20 14:07:10] VERBOSE[32452] pbx.c: [Oct 20 14:07:10] == Spawn extension (DNID_subs, sub123456, 4) exited non-zero on 'SIP/tel.t-online.de-00000059'
[Oct 20 14:07:10] DEBUG[32452] channel.c: Soft-Hanging up channel 'SIP/tel.t-online.de-00000059'
[Oct 20 14:07:10] DEBUG[32452] channel.c: Hanging up channel 'SIP/tel.t-online.de-00000059'
[Oct 20 14:07:10] DEBUG[32452] chan_sip.c: Hanging up zombie call. Be scared.
[Oct 20 14:07:10] DEBUG[32452] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x6f8058'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(start)})' (from 'CSV_QUOTE(${CDR(start)})},${CSV_QUOTE(${CDR(end)})},v,${CSV_QUOTE(${CDR(src)})},a,${CSV_QUOTE(${CDR(dst)})},ctxt,${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(answer)})},talktime,${CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 24)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(start)' (from 'CDR(start)})' len 10)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '2011-10-20 14:07:00'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"2011-10-20 14:07:00"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(end)})' (from 'CSV_QUOTE(${CDR(end)})},v,${CSV_QUOTE(${CDR(src)})},a,${CSV_QUOTE(${CDR(dst)})},ctxt,${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(answer)})},talktime,${CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 22)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(end)' (from 'CDR(end)})' len 8)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '2011-10-20 14:07:10'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"2011-10-20 14:07:10"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(src)})' (from 'CSV_QUOTE(${CDR(src)})},a,${CSV_QUOTE(${CDR(dst)})},ctxt,${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(answer)})},talktime,${CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 22)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(src)' (from 'CDR(src)})' len 8)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '+498912345678'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"+498912345678"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dst)})' (from 'CSV_QUOTE(${CDR(dst)})},ctxt,${CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(answer)})},talktime,${CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 22)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(dst)' (from 'CDR(dst)})' len 8)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is 'sub123456'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"sub123456"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(dcontext)})' (from 'CSV_QUOTE(${CDR(dcontext)})},${CSV_QUOTE(${CDR(answer)})},talktime,${CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 27)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(dcontext)' (from 'CDR(dcontext)})' len 13)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is 'DNID_subs'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"DNID_subs"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(answer)})' (from 'CSV_QUOTE(${CDR(answer)})},talktime,${CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 25)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(answer)' (from 'CDR(answer)})' len 11)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '2011-10-20 14:07:00'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"2011-10-20 14:07:00"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(billsec,f)})' (from 'CSV_QUOTE(${CDR(billsec,f)})},gdauer,${CSV_QUOTE(${CDR(duration,f)})}
' len 28)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(billsec,f)' (from 'CDR(billsec,f)})' len 14)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '9.689180'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"9.689180"'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CSV_QUOTE(${CDR(duration,f)})' (from 'CSV_QUOTE(${CDR(duration,f)})}
' len 29)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Evaluating 'CDR(duration,f)' (from 'CDR(duration,f)})' len 15)
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '9.714719'
[Oct 20 14:07:10] DEBUG[32452] pbx.c: Function result is '"9.714719"'
[Oct 20 14:07:10] DEBUG[25253] devicestate.c: No provider found, checking channel drivers for SIP - tel.t-online.de
[Oct 20 14:07:10] DEBUG[25253] chan_sip.c: Checking device state for peer tel.t-online.de
[Oct 20 14:07:10] DEBUG[25253] devicestate.c: Changing state for SIP/tel.t-online.de - state 0 (Unknown)
[Oct 20 14:07:10] DEBUG[25253] devicestate.c: device 'SIP/tel.t-online.de' state '0'
[Oct 20 14:07:11] DEBUG[25260] chan_sip.c: Destroying SIP dialog 0a8fa6020304a428@62.155.0.194
[Oct 20 14:07:11] DEBUG[25260] rtp_engine.c: Destroyed RTP instance '0x6f8058'