Daniel-Constantin Mierla writes:

Can you check that the ctx get the flag XMLRPC_DELAYED_REPLY_F set?

Otherwise, the dispatch_rpc() from xmlrpc.c is sending a response automatically.

i have not set the flag explicitly, but it should be set by call

dctx = rpc->delayed_ctx_new(c);

because xmlrpc.c/rpc_delayed_ctx_new() function sets the flag.

-- juha

Daniel-Constantin Mierla writes:

It was more to see if it is still sent inside xmlrpc_dispatch() -- perhaps you can add a log message there before rpc_send()

i added this debug to xmlrpc/dispatch_rpc():

skip: /* The function may have sent the reply itself */ if (!ctx.reply_sent) LM_INFO("function did not sent reply\n");

if (!(ctx.flags&XMLRPC_DELAYED_REPLY_F)) LM_INFO("XMLRPC_DELAYED_REPLY_F is not set\n");

if (!ctx.reply_sent && !(ctx.flags&XMLRPC_DELAYED_REPLY_F)) { ret = rpc_send(&ctx); }

and got:

Dec 4 05:55:58 rautu /usr/bin/sip-proxy[3592]: INFO: pua_rpc [pua_rpc.c:222]: publish(): pua_send_publish returned 418 Dec 4 05:55:58 rautu /usr/bin/sip-proxy[3592]: INFO: xmlrpc [xmlrpc.c:920]: rpc_fault(): running rpc_fault '500'/'Wrong ETag' Dec 4 05:55:58 rautu /usr/bin/sip-proxy[3592]: INFO: xmlrpc [xmlrpc.c:2443]: dispatch_rpc(): function did not sent reply

so looks like if callback function is not executed and

rpc->fault(c, 500, "Wrong ETag");

executed from the main function, dispatch_rpc() does not get to know about it.

-- juha

static void publish(rpc_t* rpc, void* c) ...

dctx = rpc->delayed_ctx_new(c); if (dctx == 0) { LM_ERR("internal error: failed to create context\n"); rpc->fault(c, 500, "internal error: failed to create context"); return; }

publ.cb_param = dctx; publ.source_flag = MI_ASYN_PUBLISH;

ret = pua_send_publish(&publ); LM_INFO("pua_send_publish returned %d\n", ret);

if (dctx->reply_ctx != 0) { /* callback was not executed or its execution failed */ rpc = &dctx->rpc; c = dctx->reply_ctx; } else { return; }

if (ret < 0) { LM_ERR("pua_send_publish failed\n"); err_ret = err2reason_phrase(ret, &sip_error, err_buf, sizeof(err_buf), "RPC/PUBLISH") ; if (err_ret > 0 ) { rpc->fault(c, sip_error, "%s", err_buf); } else { rpc->fault(c, 500, "RPC/PUBLISH error"); } rpc->delayed_ctx_close(dctx); }

if (ret == 418) { rpc->fault(c, 500, "Wrong ETag"); rpc->delayed_ctx_close(dctx); }

return; }

Daniel-Constantin Mierla writes:

It seems you change the value of c inside publish:

if (dctx->reply_ctx != 0) { /* callback was not executed or its execution failed */ rpc = &dctx->rpc; c = dctx->reply_ctx; } else { return; }

So it is no longer pointing to the same structure as in dispatch_rpc().

it is pointing to the same structure as in publish_callback and if the callback is executed, everything works fine:

Dec 5 07:57:02 rautu /usr/bin/sip-proxy[32714]: INFO: pua_rpc [pua_rpc.c:222]: publish(): pua_send_publish returned 0 Dec 5 07:57:02 rautu /usr/bin/sip-proxy[32714]: INFO: xmlrpc [xmlrpc.c:2441]: dispatch_rpc(): reply was not sent # T 2014/12/05 07:57:02.516438 127.0.0.1:6060 -> 127.0.0.1:54971 [AP] HTTP/1.1 200 OK. Via: SIP/2.0/TCP 127.0.0.1:54971. Server: OpenXg SIP Proxy (4.3.0-0 (i386/linux)). Content-Length: 202. . <?xml version="1.0"?> <methodResponse> <params> <param> <value><int>200</int> <string>OK</string> <string>a.1417566804.11407.5.2</string> <int>7776001</int> </value> </param> </params> </methodResponse>

the same assignments are done in tm/rpc_uac.c, which i have used as an example.

i have tried also without the assignments (see below) and also then xmlrpc debug tells that reply was not sent:

T 2014/12/05 07:45:50.696091 127.0.0.1:6060 -> 127.0.0.1:54963 [AP] HTTP/1.1 200 OK. Via: SIP/2.0/TCP 127.0.0.1:54963. Server: OpenXg SIP Proxy (4.3.0-0 (i386/linux)). Content-Length: 108. . <?xml version="1.0"?> <methodResponse> <params> <param> <value></value> </param> </params> </methodResponse> ####Dec 5 07:45:50 rautu /usr/bin/sip-proxy[32709]: INFO: pua_rpc [pua_rpc.c:222]: publish(): pua_send_publish returned 418 Dec 5 07:45:50 rautu /usr/bin/sip-proxy[32709]: INFO: xmlrpc [xmlrpc.c:2441]: dispatch_rpc(): reply was not sent

-- juha

static void publish(rpc_t* rpc, void* c) { ... dctx = rpc->delayed_ctx_new(c); if (dctx == 0) { LM_ERR("internal error: failed to create context\n"); rpc->fault(c, 500, "internal error: failed to create context"); return; }

publ.cb_param = dctx; publ.source_flag = MI_ASYN_PUBLISH;

ret = pua_send_publish(&publ); LM_INFO("pua_send_publish returned %d\n", ret);

if (dctx->reply_ctx == 0) /* callback was successfully executed */ return; ...

if (ret == 418) { rpc->fault(c, 500, "Wrong ETag"); rpc->delayed_ctx_close(dctx); }

return; }

Daniel-Constantin Mierla writes:

I see the logs messages, and it is ok that the reply was not sent message is printed, because it wasn't. But the reply is not going to be sent because there is a check on XMLRPC_DELAYED_REPLY_F flag.

I am no longer sure what behaviour you can get currently, because you haven't mentioned along with the logs here -- two replies or no-reply?

i have tried numerous variations of this and have never been able to produce a failure message when callback was not executed due to an error.

below is one variation. it closes the unused delayed context (where XMLRPC_DELAYED_REPLY_F was set) and uses the original rpc and c params to send the fault message. ngrep/syslog shows this:

Dec 5 11:52:18 rautu /usr/bin/sip-proxy[4711]: INFO: pua_rpc [pua_rpc.c:222]: publish(): pua_send_publish returned 418

T 2014/12/05 11:52:18.545314 127.0.0.1:6060 -> 127.0.0.1:56145 [AP] HTTP/1.1 200 OK. Via: SIP/2.0/TCP 127.0.0.1:56145. Server: OpenXg SIP Proxy (4.3.0-0 (i386/linux)). Content-Length: 108. . <?xml version="1.0"?> <methodResponse> <params> <param> <value></value> </param> </params> </methodResponse>

Dec 5 11:52:18 rautu /usr/bin/sip-proxy[4711]: INFO: xmlrpc [xmlrpc.c:2441]: dispatch_rpc(): reply was not sent

that is, one dummy empty reply is sent.

-- juha

#include <stdio.h> #include <stdlib.h> #include <string.h> #include <time.h>

#include "../../sr_module.h" #include "../../parser/parse_expires.h" #include "../../dprint.h" #include "../../mem/shm_mem.h" #include "../../parser/msg_parser.h" #include "../../str.h" #include "../../mem/mem.h" #include "../../pt.h" #include "../../rpc_lookup.h" #include "../../modules/tm/tm_load.h" #include "../../lib/kcore/cmpapi.h" #include "../pua/pua_bind.h"

MODULE_VERSION

static int mod_init(void);

send_publish_t pua_send_publish;

static const char* publish_doc[2] = { "sends publish request and waits for the final reply, using a list " "of string parameters: presentity uri, expires, event package, " "content type, id, etag, outbound proxy, extra headers, " " and body (optional)", 0 };

static int publish_callback(ua_pres_t* hentity, struct sip_msg* reply) { rpc_delayed_ctx_t* dctx; void* c; rpc_t* rpc; struct hdr_field* hdr= NULL; int statuscode; int expires; int found; str etag; str reason = {0, 0};

LM_DBG("running callback\n");

if (reply == NULL || hentity == NULL || hentity->cb_param == NULL) { LM_ERR("NULL reply or hentity parameter\n"); return -1; }

dctx = (rpc_delayed_ctx_t *)(hentity->cb_param); hentity->cb_param = NULL; if (dctx == 0){ BUG("null delayed reply ctx\n"); return -1; } rpc = &dctx->rpc; c = dctx->reply_ctx;

if (reply == FAKED_REPLY) { statuscode = 408; reason.s = "Request Timeout"; reason.len = strlen(reason.s); } else { statuscode = reply->first_line.u.reply.statuscode; reason = reply->first_line.u.reply.reason; } rpc->add(c, "dS", statuscode, &reason);

if (statuscode == 200) { expires = ((exp_body_t*)reply->expires->parsed)->val; LM_DBG("expires = %d\n", expires); hdr = reply->headers; found = 0; while (hdr != NULL) { if(cmp_hdrname_strzn(&hdr->name, "SIP-ETag",8) == 0) { found = 1; break; } hdr = hdr->next; } if (found == 0) { LM_ERR("SIP-ETag header field not found\n"); rpc->delayed_ctx_close(dctx); return -1; } etag = hdr->body; LM_DBG("SIP-Etag = %.*s\n", etag.len, etag.s); rpc->add(c, "Sd", &etag, expires); }

rpc->delayed_ctx_close(dctx);

return 0; }

static void publish(rpc_t* rpc, void* c) { str pres_uri, expires, event, content_type, id, etag, outbound_proxy, extra_headers, body; rpc_delayed_ctx_t* dctx; int exp, sign, ret, err_ret, sip_error; char err_buf[MAX_REASON_LEN]; struct sip_uri uri; publ_info_t publ;

body.s = 0; body.len = 0; dctx = 0;

LM_DBG("rpc publishing ...\n");

if ((rpc->capabilities == 0) || !(rpc->capabilities(c) & RPC_DELAYED_REPLY)) { rpc->fault(c, 600, "Reply wait/async mode not supported" " by this rpc transport"); return; }

ret = rpc->scan(c, "SSSSSSSS*S", &pres_uri, &expires, &event, &content_type, &id, &etag, &outbound_proxy, &extra_headers, &body); if (ret < 8) { rpc->fault(c, 400, "too few parameters (%d)", ret); return; }

if (parse_uri(pres_uri.s, pres_uri.len, &uri) <0) { LM_ERR("bad resentity uri\n"); rpc->fault(c, 400, "Invalid presentity uri '%s'", pres_uri.s); return; } LM_DBG("presentity uri '%.*s'\n", pres_uri.len, pres_uri.s);

if (expires.s[0]== '-') { sign= -1; expires.s++; expires.len--; } else { sign = 1; } if (str2int(&expires, (unsigned int*)&exp) < 0) { LM_ERR("invalid expires parameter\n" ); rpc->fault(c, 400, "Invalid expires '%s'", expires.s); return; } exp = exp * sign; LM_DBG("expires '%d'\n", exp);

LM_DBG("event '%.*s'\n", event.len, event.s);

LM_DBG("content type '%.*s'\n", content_type.len, content_type.s);

LM_DBG("id '%.*s'\n", id.len, id.s);

LM_DBG("ETag '%.*s'\n", etag.len, etag.s);

LM_DBG("outbound_proxy '%.*s'\n", outbound_proxy.len, outbound_proxy.s);

LM_DBG("extra headers '%.*s'\n", extra_headers.len, extra_headers.s);

if (body.len > 0) LM_DBG("body '%.*s'\n", body.len, body.s);

if ((body.s == 0) && (content_type.len != 1 || content_type.s[0] != '.')) { LM_ERR("body is missing, but content type is not .\n"); rpc->fault(c, 400, "Body is missing"); return; }

memset(&publ, 0, sizeof(publ_info_t)); publ.pres_uri= &pres_uri;

publ.expires= exp;

publ.event= get_event_flag(&event); if (publ.event < 0) { LM_ERR("unknown event '%.*s'\n", event.len, event.s); rpc->fault(c, 400, "Unknown event"); return; }

if (content_type.len != 1) { publ.content_type= content_type; }

if (!((id.len == 1) && (id.s[0]== '.'))) { publ.id= id; }

if (!((etag.len== 1) && (etag.s[0]== '.'))) { publ.etag= &etag; }

if (!((outbound_proxy.len == 1) && (outbound_proxy.s[0] == '.'))) { publ.outbound_proxy = &outbound_proxy; }

if (!((extra_headers.len == 1) && (extra_headers.s[0] == '.'))) { publ.extra_headers = &extra_headers; }

if (body.s != 0) { publ.body= &body; }

dctx = rpc->delayed_ctx_new(c); if (dctx == 0) { LM_ERR("internal error: failed to create context\n"); rpc->fault(c, 500, "internal error: failed to create context"); return; }

publ.cb_param = dctx; publ.source_flag = MI_ASYN_PUBLISH;

ret = pua_send_publish(&publ); LM_INFO("pua_send_publish returned %d\n", ret);

if (dctx->reply_ctx == 0) /* callback was successfully executed */ return; else /* close unused delayed context */ (&dctx->rpc)->delayed_ctx_close(dctx);

if (ret < 0) { LM_ERR("pua_send_publish failed\n"); err_ret = err2reason_phrase(ret, &sip_error, err_buf, sizeof(err_buf), "RPC/PUBLISH") ; if (err_ret > 0 ) { rpc->fault(c, sip_error, "%s", err_buf); } else { rpc->fault(c, 500, "RPC/PUBLISH error"); } }

if (ret == 418) { rpc->fault(c, 500, "Wrong ETag"); }

return; }

rpc_export_t pua_rpc[] = { {"pua.publish", publish, publish_doc, 0}, {0, 0, 0, 0} };

/** module exports */ struct module_exports exports= { "pua_rpc", 0, pua_rpc, 0, mod_init, 0, 0, 0, 0 }; /** * init module function */ static int mod_init(void) { bind_pua_t bind_pua; pua_api_t pua;

LM_DBG("initializing\n"); bind_pua= (bind_pua_t)find_export("bind_pua", 1,0);

if (!bind_pua) { LM_ERR("can't find pua\n"); return -1; } if (bind_pua(&pua) < 0) { LM_ERR("can't bind pua\n"); return -1; }

if (pua.send_publish == NULL) { LM_ERR("could not import send_publish\n"); return -1; } pua_send_publish = pua.send_publish;

if (pua.register_puacb(MI_ASYN_PUBLISH, publish_callback, NULL) < 0) { LM_ERR("could not register callback\n"); return -1; }

return 0; }

Daniel-Constantin Mierla writes:

Can you try setting the fault to delayed context, like:

rpc->fault(dctx, 500, "Wrong ETag");

same thing:

T 2014/12/05 12:40:30.119921 127.0.0.1:6060 -> 127.0.0.1:56354 [AP] HTTP/1.1 200 OK. Via: SIP/2.0/TCP 127.0.0.1:56354. Server: OpenXg SIP Proxy (4.3.0-0 (i386/linux)). Content-Length: 108. . <?xml version="1.0"?> <methodResponse> <params> <param> <value></value> </param> </params> </methodResponse>

Dec 5 12:40:30 rautu /usr/bin/sip-proxy[5833]: INFO: pua_rpc [pua_rpc.c:222]: publish(): pua_send_publish returned 418 Dec 5 12:40:30 rautu /usr/bin/sip-proxy[5833]: INFO: xmlrpc [xmlrpc.c:2441]: dispatch_rpc(): reply was not sent

-- juha

... dctx = rpc->delayed_ctx_new(c); if (dctx == 0) { LM_ERR("internal error: failed to create context\n"); rpc->fault(c, 500, "internal error: failed to create context"); return; }

publ.cb_param = dctx; publ.source_flag = MI_ASYN_PUBLISH;

ret = pua_send_publish(&publ); LM_INFO("pua_send_publish returned %d\n", ret);

if (dctx->reply_ctx == 0) /* callback was successfully executed */ return;

if (ret < 0) { LM_ERR("pua_send_publish failed\n"); err_ret = err2reason_phrase(ret, &sip_error, err_buf, sizeof(err_buf), "RPC/PUBLISH") ; if (err_ret > 0 ) { rpc->fault(dctx, sip_error, "%s", err_buf); } else { rpc->fault(dctx, 500, "RPC/PUBLISH error"); } }

if (ret == 418) { rpc->fault(dctx, 500, "Wrong ETag"); }

(&dctx->rpc)->delayed_ctx_close(dctx);

return; }