Dial Plan stops processing when it hits a CURL

[Spetnik]

I cannot seem to get CURL working in my dial plan. The call to the server is actually made and data returned (the remote server apache logs and asterisk debug logs confirm that), but the dial plan just stops processing at that point.

Asterisk was compiled with CURL and the latest versions of all CURL libraries are installed on the server.

Here is a snippet from my dial plan:

Code: Select all

exten => _X!,n,Set(CURLOPT(conntimeout)=1)
exten => _X!,n,Set(CURLOPT(httptimeout)=1)
exten => _X!,n,NoOp(Before)
exten => _X!,n,NoOp(${CURL(http://www.spetnik.com/t.txt)})
exten => _X!,n,NoOp(After)


The dial plan processes fine until it hits the CURL line, as seen below. Then it just stops and after a few seconds the dial plan starts again from the beginning. This pattern repeats until the call disconnects.

Code: Select all

    -- Executing [13144882555@from-trunk-custom:4] Set("SIP/Trunk-000000ab", "CURLOPT(conntimeout)=1") in new stack
    -- Executing [13144882555@from-trunk-custom:5] Set("SIP/Trunk-000000ab", "CURLOPT(httptimeout)=1") in new stack
    -- Executing [13144882555@from-trunk-custom:6] NoOp("SIP/Trunk-000000ab", "Before") in new stack


[thor]

Please post your logs showing the problem ( including timestamps ) not the snapshot of the partial console output.

[david55]

And not cut short just before the point which might be interesting!

[Spetnik]

I called and let it ring for about 90 seconds. Here is the full log: http://pastebin.com/NSSJfmgk

[Spetnik]

Bump - any ideas why CURL is messing up the dial plan?

[david55]

The caller abandoned the call before the CURL completed, resulting in the curl being abandoned. I'm not actually convinced that the curl has completed before the end of the trace, but it will have no channel when it does complete.

I could have done without the AMI event traces. I probably could have done with having the SIP protocol traced.

My guess is that you have broken DNS for the destination, but it could also simply be that the web server takes too long to respond.

[Spetnik]

The caller did not abandon - I have tried it myself from different carriers. Additionally, the process repeats several times (i.e. multiple CURL requests) during a single call. The logs posted even show the contents of the CURL response. DNS is not the issue, as a) the CURL request does return, b) the remote server logs the request, and c) CURL to that server works fine from the shell or php. Finally, the web server returns very quickly - and even if it did not, it should time out and return to the dial plan.

I am new to Asterisk, so please let me know how to produce a log with SIP tracing and no AMI event traces and I will post that as well.

Thanks

[david55]

The caller did abandon. Asterisk is quite clearly reporting the receipt of a SIP CANCEL, which can only happen if a caller abandons before the call is answered.

To get the sip trace, use "sip set debug on". I've never seen a trace with all the AMI events before, so maybe you just set the debugging level a bit high.

[Spetnik]

Okay, I did another call. I initiated the call at 19:56:57 and I did not disconnect the call until 19:57:58.

Here are the logs with verbose=3, debug=3, and sip debug=on: http://pastebin.com/qG3cEP5h

As you can see, CURL returns within one second (lines 264-281)

Thanks

[david55]

Which version of Asterisk are us using (the SIP only gives a FreePBX version)? My oldish version has none of the trace lines in func_curl.c. However, it also has no points where it could block, except within the curl library itself.

Also, I don't understand the bit about the dialplan starting over. The thread that is running the dialplan doesn't produce any further output after that from func_curl.c, so it is is actually freezing, not looping back to the beginning.

I suspect you may need to get a backtrace, to find out where the thread is waiting.

[Spetnik]

I am running 1.8.13.0.

Pardon me if I am incorrect, but aren't backtraces only produced when Asterisk crashes? Asterisk is running with -g, but no "core" files are being produced.

Also, I just realized: this log was from a call from a Google Voice number. I think Google Voice may try multiple times (while ringing) if the call fails. I tried from another carrier and the call failed after about 20 seconds without ever ringing.

[Spetnik]

Figured out how to do a backtrace. See http://pastebin.com/m8TZtkJQ
Is that what you wanted?

[david55]

If that was run between when the curl stalled and the caller abandoned, something is definitely wrong, as there is no thread there that is running dialplan code. The LWP value should match the value in square brackets on the curl traces.

If a worker thread actually crashes, the whole of Asterisk, will crash. Threads running dialplan should not terminate except after outputting the trace for the last dialplan line attempted, and some trace relating to exiting. A dialplan thread exit should also initiate a close on the incoming SIP connection.

If the backtrace was taken when the symptoms should have been present, I think you need to check that you are using the latest 1.8 build, and if so, take this to issues.asterisk.org, as a bug report.

[Spetnik]

It was run from before the call initiated until after termination. I was running Asterisk 1.8.13.0 but I just upgraded to 10.5.2 and still have the problem.

[david55]

As a starting point for the bug report title, I would suggest something like:

PBX thread terminates silently (no crash) in or after func_curl.c

[Spetnik]

Thanks