Error in log because PJSIP removing header when none exist

So, new FreePBX 15 system, using only chan_pjsip.

Every single calls get this an error in the log.

ERROR[11122] res_pjsip_header_funcs.c: No headers had been previously added to this session.

It looks like it is happening because func-apply-sipheaders is removing where there is nothing.

This was added to ensure that Alert-Info headers, if set, get removed before calls goes to trunk. There were reports of this header causing trunk calls to fail. If the header is not already set, then it triggers the noted error, but apart from messy logs, there is no other consequence to that.

It prob could be cleaner, so open a ticket if you’re included, but unless it’s causing more problems than a log line, it will not be given a high priority.

So looking at the generated dial plan…

include => func-apply-sipheaders-custom
exten => s,1,Noop(Applying SIP Headers to channel ${CHANNEL})
exten => s,n,Set(TECH=${CUT(CHANNEL,/,1)})
exten => s,n,Set(SIPHEADERKEYS=${HASHKEYS(SIPHEADERS)})
exten => s,n,While($["${SET(sipkey=${SHIFT(SIPHEADERKEYS)})}" != ""])
exten => s,n,Set(sipheader=${HASH(SIPHEADERS,${sipkey})})
exten => s,n,ExecIf($["${sipheader}" = "unset" & "${TECH}" = "PJSIP"]?Set(PJSIP_HEADER(remove,${sipkey})=))
exten => s,n,ExecIf($["${sipheader}" != "unset" & "${sipkey}" = "Alert-Info" & ${REGEX("^<[^>]*>" ${sipheader})} != 1 & ${REGEX("\;info=" ${sipheader})} != 1]?Set(sipheader=<http://127.0.0.1>\;info=${sipheader}))
exten => s,n,ExecIf($["${sipheader}" != "unset" & "${sipkey}" = "Alert-Info" & ${REGEX("^<[^>]*>" ${sipheader})} != 1]?Set(sipheader=<http://127.0.0.1>${sipheader}))
exten => s,n,ExecIf($["${TECH}" = "PJSIP" & "${sipheader}" != "unset"]?Set(PJSIP_HEADER(add,${sipkey})=${sipheader}))
exten => s,n,EndWhile
exten => s,n,Return()

;--== end of [func-apply-sipheaders] ==--;

This bit

exten => s,n,Set(sipheader=${HASH(SIPHEADERS,${sipkey})})

is returning "unset"

So I copied this routine to /etc/asterisk/extensions_override_freepbx.conf and dropped a couple NoOp’s in there for detail, it seems that “Alert-Info” always exists.
exten => s,n,NoOp(Alert-Info is currently set to: ${PJSIP_HEADER(read,Alert-Info)})

No matter where I had those (at one point after every line), it always returned empty.

[[email protected] ~]$ tail -f /var/log/asterisk/full | grep "NoOp\|Noop\|ERROR"
[2021-02-18 14:09:04] VERBOSE[18600][C-000004db] pbx.c: Executing [[email protected]:5] NoOp("PJSIP/103-000009e1", "PJSIP/Skyetel-000009e2 montior file= ") in new stack
[2021-02-18 14:10:19] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:20] NoOp("PJSIP/103-000009e3", "[TRACE](3) Current Concurrency Count for 103: 0, User Limit: 3") in new stack
[2021-02-18 14:10:19] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:24] NoOp("PJSIP/103-000009e3", "Macro Depth is 1") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:51] NoOp("PJSIP/103-000009e3", "[TRACE](3) Using CallerID "Jared Busch" <103>") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/103-000009e3", "Recordings initialized") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/103-000009e3", "Outbound Recording Check from 103 to 314NXXXXXX") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/103-000009e3", "Starting recording check against dontcare") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:3] NoOp("PJSIP/103-000009e3", "[TRACE](1) Calling Out Route: Normal_Out") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/103-000009e3", "103") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:2] NoOp("PJSIP/103-000009e3", "") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:3] NoOp("PJSIP/103-000009e3", "off") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/103-000009e3", "Entering user defined context [macro-dialout-trunk-predial-hook] in extensions_custom.conf") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/103-000009e3", "Trunk Name: @Skyetel") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:12] NoOp("PJSIP/103-000009e3", "We are heading for the Skyetel Trunk, determine the X-Tenant based on outbound route") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:17] NoOp("PJSIP/103-000009e3", "Based on the outbound route name of Normal_Out, the X-Tenant is being set to bundy.") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/103-000009e3", "Sip Add Header function called. Adding X-Tenant = bundy") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/Skyetel-000009e4", "Applying SIP Headers to channel PJSIP/Skyetel-000009e4") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:2] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:4] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:6] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:7] NoOp("PJSIP/Skyetel-000009e4", "Before Current Alert-Info = ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:8] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:12] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:13] NoOp("PJSIP/Skyetel-000009e4", "Current sipkey = Alert-Info and sipheader = unset") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:14] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:16] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] ERROR[23828] res_pjsip_header_funcs.c: No headers had been previously added to this session.
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:18] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:20] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:22] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:24] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:26] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:12] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:13] NoOp("PJSIP/Skyetel-000009e4", "Current sipkey = X-Tenant and sipheader = bundy") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:14] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:16] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:18] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:20] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:22] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:24] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:26] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:20] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:28] NoOp("PJSIP/Skyetel-000009e4", "Alert-Info is currently set to:  ") in new stack
[2021-02-18 14:10:24] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:2] NoOp("PJSIP/Skyetel-000009e4", "email notifications disabled..exiting.") in new stack
[2021-02-18 14:10:28] VERBOSE[18894][C-000004dc] pbx.c: Executing [[email protected]:5] NoOp("PJSIP/103-000009e3", "PJSIP/Skyetel-000009e4 montior file= ") in new stack

I could 100% break my outbound calling by setting Alert-Info manually to “Testing” after the while loop.

exten => s,n,Set(PJSIP_HEADER(add,Alert-Info)=Testing)

Manually setting it to a similar form as the generated context kept calls flowing.

exten => s,n,Set(PJSIP_HEADER(add,Alert-Info)=<http://127.0.0.1>\;info=Testing)

So should the dial plan logic be smarter, or should Asterisk be updated to more gracefully handle a remove when nothing has been previously set?

1 Like

if its not an error it shouldn’t be reported as one … fwconsole debug is testament to this as well

my 3 cents

1 Like

So is your opinion that this is on Asterisk to not report as an error? but as an info or warning?

This is definitely a bug in FreePBX core.

The line that generates the ERROR message is line 10687 from /etc/asterisk/extensions_additional.conf (see below).

The logic is flawed which is why it generates an ERROR for 100% of every PJSIP call made.

It says: If any entry in SIPHEADERS array is “unset” for a PJSIP channel call, attempt to remove that header from the (not yet populated) out going SIP header.

But, this is part of func-apply-sipheaders which is supposed be adding headers. At this point in the call setup, the SIPHEADERS have not been added, so they can’t be removed with PJSIP_HEADER(remove, header).

Luckily, there is only one entry in the SIPHEADERS array. If there were more, it would generate an ERROR message for each header for every single PJSIP call. :face_vomiting:

It’s funny because line 10690, three lines after, says: If the entry is not “unset” for a PJSIP channel, go ahead and call PJSIP_HEADER() to add it to the out going SIP header.

In other words an “unset” PJSIP header won’t be added any way.

FWIW, the other two lines (10688 & 10689) make a feeble attempt to fix malformed Alert-Info header values by changing them to: <http://172.0.0.1>;info=malformed-header-value The two lines are only included if the Enforce RFC7462 option is set to Yes under Settings > Advanced Settings.

The logic is seriously flawed, and should probably just generate an ERROR message and drop the malformed header by setting its value to “unset”. But, that’s not what’s causing the ERROR messages.

The workaround for this until it gets fixed in core is to copy the func-apply-sipheaders block (lines 10680 to 10694) into /etc/asterisk/extensions_override_freepbx.conf and then comment out or delete what was line 19687. Then run sudo rasterisk -x 'dialplan reload' to regenerate the dial plan.

@lgaetz, you mentioned that @sorvani should open a ticket somewhere. Where is the best place to report this issue? It definitely needs to be fixed.

/etc/asterisk/extensions_additional.conf:

 10680  [func-apply-sipheaders]
 10681  include => func-apply-sipheaders-custom
 10682  exten => s,1,Noop(Applying SIP Headers to channel ${CHANNEL})
 10683  exten => s,n,Set(TECH=${CUT(CHANNEL,/,1)})
 10684  exten => s,n,Set(SIPHEADERKEYS=${HASHKEYS(SIPHEADERS)})
 10685  exten => s,n,While($["${SET(sipkey=${SHIFT(SIPHEADERKEYS)})}" != ""])
 10686  exten => s,n,Set(sipheader=${HASH(SIPHEADERS,${sipkey})})
 10687  exten => s,n,ExecIf($["${sipheader}" = "unset" & "${TECH}" = "PJSIP"]?Set(PJSIP_HEADER(remove,${sipkey})=))
 10688  exten => s,n,ExecIf($["${sipheader}" != "unset" & "${sipkey}" = "Alert-Info" & ${REGEX("^<[^>]*>" ${sipheader})} != 1 & ${REGEX("\;info=" ${sipheader})} != 1]?Set(sipheader=<http://127.0.0.1>\;info=${sipheader}))
 10689  exten => s,n,ExecIf($["${sipheader}" != "unset" & "${sipkey}" = "Alert-Info" & ${REGEX("^<[^>]*>" ${sipheader})} != 1]?Set(sipheader=<http://127.0.0.1>${sipheader}))
 10690  exten => s,n,ExecIf($["${TECH}" = "PJSIP" & "${sipheader}" != "unset"]?Set(PJSIP_HEADER(add,${sipkey})=${sipheader}))
 10691  exten => s,n,EndWhile
 10692  exten => s,n,Return()
 10693
 10694  ;--== end of [func-apply-sipheaders] ==--;```

It’s just a bug. It should do neither.

Not an Asterisk bug, FreePBX sure. This is due to generated dialplan.

1 Like

It is visible because of the generated dial plan. Yes.

But my question was should pjsip generate an error when told to remove something or not?

Reading the error it seems to be saying nothing was previously set. Yet reading the headers directly returns as an emtpy string. Which the hash turns into “unset”

And I already have an issue open on this for FreePBX.

Edit: Well I thought I opened an issue. Maybe I left that tab submitted as I cannot find it. I am on my phone right now.

My bad. I took out the reference to Asterisk. Thx!

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.