Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Daniel Tryba 
On Sun, Jun 11, 2017 at 01:16:10PM +0200, Michael Maier wrote:
> Let's go into details:
> I'm starting at the point where asterisk / fax client receives the T.38
> reininvite from the server from the provider 195.185.37.60:5060 for the
> fax client (extension 91):

I'm running Asterisk 11 on my faxserver so not using pjsip but chan_sip.
But IIRC I had problems with asterisk-11/t38modem-2.0.0/hylafax if the
upstream side started the t38 reINVITE on sending a fax. My hylafax
config.ttyT38* contains the AT F command to initiale t38 on the t38modem
side for outgoing calls. For incoming t38modem also starts the reINVITE
but there is no parameter to influence this in my configs.

No idea if this is in anyway related nor what the default is of the
options below and neither if it depends on the t38modem version.

# T.38 dial modifiers
#
# F - enable T.38 mode request after dialing
# V - disable T.38 mode request after dialing (remote host should do it)
#
# calling/called number dial modifiers
#
# L - reset and begin of calling number
# D - continue of called number
#
ModemDialCmd:   ATDF%s  # user can override F by dial V
#ModemDialCmd:  ATDV%s  # user can override V by dial F
#ModemDialCmd:  ATD%sF  # user can't override F
#ModemDialCmd:  ATD%sV  # user can't override V
#ModemDialCmd:  ATD%sVL # user can't override V or calling 
number


-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Joshua Colp 
On Sun, Jun 11, 2017, at 01:47 PM, Joshua Colp wrote:
> On Sun, Jun 11, 2017, at 01:31 PM, Michael Maier wrote:
> > On 06/11/2017 at 04:39 PM Joshua Colp wrote:
> > > On Sun, Jun 11, 2017, at 11:34 AM, Michael Maier wrote:
> > > 
> > > 
> > > 
> > >>>
> > >>> PJSIP uses a dispatch model. The request is queued up, acted on, and
> > >>> then that's it. The act of acting on it removes it from the queue.
> > >>
> > >> That's the *expected* behavior ... . I rechecked again and again. All
> > >> existing tcpdumps. The "resent" package isn't part of any tcpdump
> > >> (wireshark doesn't show it) - and during tcpdump no package was dropped.
> > >>
> > >>> The
> > >>> only reason I'd expect to see it again is if there was a retransmission
> > >>> or something somehow requeued it up - but I don't think we do that
> > >>> anywhere. Not quite sure why it would be happening...
> > >>
> > >> But even if this package would have really been sent (as retransmission)
> > >> - shouldn't there be another response? T.38 has been successfully
> > >> enabled before and the faxclient has already sent a valid 200 ok
> > >> including complete SDP information to asterisk.
> > >>
> > >> All in all it looks really odd to me.
> > > 
> > > Depends on how we handle that scenario. I don't think we have any tests
> > > to cover it, so it's entirely possible that we wouldn't respond like
> > > that. Why it's happening in the first place I still don't know though,
> > > haven't seen anything like it.
> > 
> > Do you have any idea where to check if acted packages are really
> > removed? Is there a way to check the pjsip-queue? Where could I start to
> > look at? How does asterisk get them from the queue? And how does pjsip
> > know that asterisk has processed them?
> 
> The distributor is in res/res_pjsip/pjsip_distributor.c, the distributor
> function being the entry point. That function returning PJ_TRUE
> indicates to PJSIP that it has been handled and no subsequent modules
> should be called by that running thread. The distributor itself, though,
> ends up executing things further in a worker thread using the distribute
> function.

To be more detailed - PJSIP maintains no queue, a message comes in from
a transport and is given to modules until one says it has handled the
message. We place our distributor close to the transport and it puts the
message into a queue for handling in Asterisk ensuring serialization as
appropriate, returning that it has handled the message so no other
modules handle it at that time. Once the message is handled from the
queue it picks back up invoking modules at the point where the original
thread left off. This ensures messages are handled as quickly as
possible without blocking the transport but also provides guarantees on
ordering and simultaneous execution. (Two messages for the same call
will be handled in order, one at a time).

-- 
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Joshua Colp 
On Sun, Jun 11, 2017, at 01:31 PM, Michael Maier wrote:
> On 06/11/2017 at 04:39 PM Joshua Colp wrote:
> > On Sun, Jun 11, 2017, at 11:34 AM, Michael Maier wrote:
> > 
> > 
> > 
> >>>
> >>> PJSIP uses a dispatch model. The request is queued up, acted on, and
> >>> then that's it. The act of acting on it removes it from the queue.
> >>
> >> That's the *expected* behavior ... . I rechecked again and again. All
> >> existing tcpdumps. The "resent" package isn't part of any tcpdump
> >> (wireshark doesn't show it) - and during tcpdump no package was dropped.
> >>
> >>> The
> >>> only reason I'd expect to see it again is if there was a retransmission
> >>> or something somehow requeued it up - but I don't think we do that
> >>> anywhere. Not quite sure why it would be happening...
> >>
> >> But even if this package would have really been sent (as retransmission)
> >> - shouldn't there be another response? T.38 has been successfully
> >> enabled before and the faxclient has already sent a valid 200 ok
> >> including complete SDP information to asterisk.
> >>
> >> All in all it looks really odd to me.
> > 
> > Depends on how we handle that scenario. I don't think we have any tests
> > to cover it, so it's entirely possible that we wouldn't respond like
> > that. Why it's happening in the first place I still don't know though,
> > haven't seen anything like it.
> 
> Do you have any idea where to check if acted packages are really
> removed? Is there a way to check the pjsip-queue? Where could I start to
> look at? How does asterisk get them from the queue? And how does pjsip
> know that asterisk has processed them?

The distributor is in res/res_pjsip/pjsip_distributor.c, the distributor
function being the entry point. That function returning PJ_TRUE
indicates to PJSIP that it has been handled and no subsequent modules
should be called by that running thread. The distributor itself, though,
ends up executing things further in a worker thread using the distribute
function.

-- 
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Michael Maier 
On 06/11/2017 at 04:39 PM Joshua Colp wrote:
> On Sun, Jun 11, 2017, at 11:34 AM, Michael Maier wrote:
> 
> 
> 
>>>
>>> PJSIP uses a dispatch model. The request is queued up, acted on, and
>>> then that's it. The act of acting on it removes it from the queue.
>>
>> That's the *expected* behavior ... . I rechecked again and again. All
>> existing tcpdumps. The "resent" package isn't part of any tcpdump
>> (wireshark doesn't show it) - and during tcpdump no package was dropped.
>>
>>> The
>>> only reason I'd expect to see it again is if there was a retransmission
>>> or something somehow requeued it up - but I don't think we do that
>>> anywhere. Not quite sure why it would be happening...
>>
>> But even if this package would have really been sent (as retransmission)
>> - shouldn't there be another response? T.38 has been successfully
>> enabled before and the faxclient has already sent a valid 200 ok
>> including complete SDP information to asterisk.
>>
>> All in all it looks really odd to me.
> 
> Depends on how we handle that scenario. I don't think we have any tests
> to cover it, so it's entirely possible that we wouldn't respond like
> that. Why it's happening in the first place I still don't know though,
> haven't seen anything like it.

Do you have any idea where to check if acted packages are really
removed? Is there a way to check the pjsip-queue? Where could I start to
look at? How does asterisk get them from the queue? And how does pjsip
know that asterisk has processed them?



Thanks,
Michael

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Joshua Colp 
On Sun, Jun 11, 2017, at 11:34 AM, Michael Maier wrote:



> > 
> > PJSIP uses a dispatch model. The request is queued up, acted on, and
> > then that's it. The act of acting on it removes it from the queue.
> 
> That's the *expected* behavior ... . I rechecked again and again. All
> existing tcpdumps. The "resent" package isn't part of any tcpdump
> (wireshark doesn't show it) - and during tcpdump no package was dropped.
> 
> > The
> > only reason I'd expect to see it again is if there was a retransmission
> > or something somehow requeued it up - but I don't think we do that
> > anywhere. Not quite sure why it would be happening...
> 
> But even if this package would have really been sent (as retransmission)
> - shouldn't there be another response? T.38 has been successfully
> enabled before and the faxclient has already sent a valid 200 ok
> including complete SDP information to asterisk.
> 
> All in all it looks really odd to me.

Depends on how we handle that scenario. I don't think we have any tests
to cover it, so it's entirely possible that we wouldn't respond like
that. Why it's happening in the first place I still don't know though,
haven't seen anything like it.

-- 
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Michael Maier 
On 06/11/2017 at 01:29 PM Joshua Colp wrote:
> On Sun, Jun 11, 2017, at 08:16 AM, Michael Maier wrote:
> 
> 
>  
>> I did some further investigations and fixed a local problem. Now,
>> asterisk is able to successfully activate T.38 - unfortunately just for
>> very shot time because of a phantom package it receives!
> 
> What was the local problem?

Update of t38modem from 3.13 to 3.15

>> Let's go into details:
>> I'm starting at the point where asterisk / fax client receives the T.38
>> reininvite from the server from the provider 195.185.37.60:5060 for the
>> fax client (extension 91):
> 
> 
> 
>>
>> But now, something strange happens: Asterisk "receives" a T.38 reinvite
>> package from provider!
>> Why is it strange? Because *this package doesn't exist at all* ! It
>> can't be seen in tcpdump. I did 4 tests - always the same! Where does
>> this package come from? It's exactly the same package which can be seen
>> at the beginning of the trace excerpted here! Isn't it been deleted
>> after it has been processed the first time?
> 
> PJSIP uses a dispatch model. The request is queued up, acted on, and
> then that's it. The act of acting on it removes it from the queue.

That's the *expected* behavior ... . I rechecked again and again. All
existing tcpdumps. The "resent" package isn't part of any tcpdump
(wireshark doesn't show it) - and during tcpdump no package was dropped.

> The
> only reason I'd expect to see it again is if there was a retransmission
> or something somehow requeued it up - but I don't think we do that
> anywhere. Not quite sure why it would be happening...

But even if this package would have really been sent (as retransmission)
- shouldn't there be another response? T.38 has been successfully
enabled before and the faxclient has already sent a valid 200 ok
including complete SDP information to asterisk.

All in all it looks really odd to me.


Thanks,
regards,
Michael

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Joshua Colp 
On Sun, Jun 11, 2017, at 08:16 AM, Michael Maier wrote:


 
> I did some further investigations and fixed a local problem. Now,
> asterisk is able to successfully activate T.38 - unfortunately just for
> very shot time because of a phantom package it receives!

What was the local problem?
 
> Let's go into details:
> I'm starting at the point where asterisk / fax client receives the T.38
> reininvite from the server from the provider 195.185.37.60:5060 for the
> fax client (extension 91):



> 
> But now, something strange happens: Asterisk "receives" a T.38 reinvite
> package from provider!
> Why is it strange? Because *this package doesn't exist at all* ! It
> can't be seen in tcpdump. I did 4 tests - always the same! Where does
> this package come from? It's exactly the same package which can be seen
> at the beginning of the trace excerpted here! Isn't it been deleted
> after it has been processed the first time?

PJSIP uses a dispatch model. The request is queued up, acted on, and
then that's it. The act of acting on it removes it from the queue. The
only reason I'd expect to see it again is if there was a retransmission
or something somehow requeued it up - but I don't think we do that
anywhere. Not quite sure why it would be happening...

-- 
Joshua Colp
Digium, Inc. | Senior Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - US
Check us out at: www.digium.com & www.asterisk.org

-- 
_
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

Check out the new Asterisk community forum at: https://community.asterisk.org/

New to Asterisk? Start here:
  https://wiki.asterisk.org/wiki/display/AST/Getting+Started

asterisk-users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

Re: [asterisk-users] asterisk 13.16 / pjsip / t.38: res_pjsip_t38.c:207 t38_automatic_reject: Automatically rejecting T.38 request on channel 'PJSIP/91-00000007'

2017-06-11 Thread Michael Maier 
On 06/05/2017 at 09:32 PM Joshua Colp wrote:
> On Mon, Jun 5, 2017, at 04:26 PM, Michael Maier wrote:
>> On 06/05/2017 at 06:29 PM, Joshua Colp wrote:
>>> On Mon, Jun 5, 2017, at 01:22 PM, Michael Maier wrote:

 Do you have any idea where to start to look at? Adding additional output
 in the source code? Which functions could be interesting? I may add own
 debug code to see why things are happening as they happen here.
>>>
>>> The logic for T.38 negotiation lives all in the res_pjsip_t38 module and
>>> the request to negotiate works using a control frame which is handled by
>>> the t38_interpret_parameters function. It's up to that to initialize
>>> things and then request that a session refresh occurs (which sends the
>>> re-invite). That'd be the place to look.
>>
>> I added a debug output at the beginning of the function to see if it's
>> ever 
>> been called.
>>
>> t38_interpret_parameters is never been called ... .
> 
> That would likely mean that the frame is not getting sent (this also
> happens in that module) or that it is getting lost in the bridging
> framework. Digging into that is not something that can be expressed in
> general terms in email...

I did some further investigations and fixed a local problem. Now,
asterisk is able to successfully activate T.38 - unfortunately just for
very shot time because of a phantom package it receives!

Let's go into details:
I'm starting at the point where asterisk / fax client receives the T.38
reininvite from the server from the provider 195.185.37.60:5060 for the
fax client (extension 91):



<--- Received SIP request (918 bytes) from UDP:195.185.37.60:5060 --->
INVITE sip:+4971511336089@42.21.35.43:5061 SIP/2.0
Via: SIP/2.0/UDP 195.185.37.60;branch=z9hG4bKd8EHOaij;rport
From: ;tag=124E09F9-593D01CC00045378-134F4700
To: 
;tag=dd67e8fd-cd74-40e2-bf58-dc99b182aec9
CSeq: 10 INVITE
Call-ID: c34cc459-96f3-47a6-8279-d46cddf9abb7
Max-Forwards: 68
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, 
PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Content-Type: application/sdp
Content-Length: 265
Contact: 

v=0
o=- 2068461195 2068461199 IN IP4 195.185.37.60
s=-
c=IN IP4 195.185.37.60
t=0 0
m=image 24842 UDPTL t38
a=sendrecv
a=T38FaxVersion:0
a=T38MaxBitRate:14400
a=T38FaxRateManagement:transferredTCF
a=T38FaxMaxDatagram:1393
a=T38FaxUdpEC:t38UDPRedundancy

[2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:379 
distributor: Searching for serializer on dialog dlg0x7fdde801e258 for Request 
msg INVITE/cseq=10 (rdata0x7fddb4012488)
[2017-06-11 10:39:42] DEBUG[24434]: res_pjsip/pjsip_distributor.c:385 
distributor: Found serializer pjsip/outsess/easybellPJSIP-0076 on dialog 
dlg0x7fdde801e258
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:268 t38_initialize_session: 
UDPTL initialized on session for PJSIP/easybellPJSIP-0005
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:138 t38_change_state: T.38 
state changed to '2' from '0' on channel 'PJSIP/easybellPJSIP-0005'
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:696 
defer_incoming_sdp_stream: Deferring incoming SDP stream on 
PJSIP/easybellPJSIP-0005 for peer re-invite
[2017-06-11 10:39:42] DEBUG[25987][C-0002]: bridge_native_rtp.c:348 
native_rtp_bridge_compatible_check: Bridge 
'a10ac2c1-5045-4a7d-ada4-6a6e54671b9d' can not use native RTP bridge as it was 
forbidden while getting details
[2017-06-11 10:39:42] DEBUG[25987][C-0002]: bridge.c:506 
find_best_technology: Bridge technology native_rtp is not compatible with 
properties of existing bridge.
[2017-06-11 10:39:42] DEBUG[25987][C-0002]: bridge.c:496 
find_best_technology: Bridge technology softmix does not have any capabilities 
we want.
[2017-06-11 10:39:42] DEBUG[25987][C-0002]: bridge.c:496 
find_best_technology: Bridge technology holding_bridge does not have any 
capabilities we want.
[2017-06-11 10:39:42] DEBUG[25987][C-0002]: bridge.c:515 
find_best_technology: Chose bridge technology simple_bridge
[2017-06-11 10:39:42] DEBUG[25987][C-0002]: bridge.c:1046 
smart_bridge_operation: Bridge a10ac2c1-5045-4a7d-ada4-6a6e54671b9d is already 
using the new technology.
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:268 t38_initialize_session: 
UDPTL initialized on session for PJSIP/91-0004
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_t38.c:138 t38_change_state: T.38 
state changed to '1' from '0' on channel 'PJSIP/91-0004'
[2017-06-11 10:39:42] DEBUG[25822]: res_rtp_asterisk.c:5342 ast_rtp_prop_set: 
Ignoring duplicate RTCP property on RTP instance '0x7fddc8011b10'
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:971 
ast_sip_session_refresh: Sending session refresh SDP via re-INVITE to 91
[2017-06-11 10:39:42] DEBUG[25822]: res_pjsip_session.c:2501