2 Nov
2020
2 Nov
'20
11:15 p.m.
Nov 2 21:13:28 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_EXPIRED,
lets retrieve a new one
Nov 2 21:13:28 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_RECEIVED,
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjA4LCJleHAiOjE2MDQzNTUyMDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351608,"exp":1604355208,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"
brandon(a)cryy.com
"},"source":{"address":"34.94.123.121"}},"signature":"sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog"}}}
Nov 2 21:13:28 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_TIME,
1604351608
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 11
size: 1
slot: {
{
name: auth::token
value:
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjA4LCJleHAiOjE2MDQzNTUyMDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351608,"exp":1604355208,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"
brandon(a)cryy.com
"},"source":{"address":"34.94.123.121"}},"signature":"sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog"}}}
type: str
}
}
}
Nov 2 21:13:48 main kamailio[1334]: INFO: <script>: AUTH_TOKEN_EXPIRED,
lets retrieve a new one
Nov 2 21:13:48 main kamailio[1334]: INFO: <script>: AUTH_TOKEN_RECEIVED,
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjI4LCJleHAiOjE2MDQzNTUyMjgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.stW5JzPR-Gz3oVvQEb1wxF7I0GcZ1KjkkQhinHGEivQ","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351628,"exp":1604355228,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"
brandon(a)cryy.com
"},"source":{"address":"34.94.123.121"}},"signature":"stW5JzPR-Gz3oVvQEb1wxF7I0GcZ1KjkkQhinHGEivQ"}}}
Nov 2 21:13:48 main kamailio[1334]: INFO: <script>: AUTH_TOKEN_TIME,
1604351628
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 0
size: 1
slot: {
{
name: auth::time
value: 1604351628
type: int
}
}
}
Nov 2 21:14:08 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_EXPIRED,
lets retrieve a new one
Nov 2 21:14:08 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_RECEIVED,
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjQ4LCJleHAiOjE2MDQzNTUyNDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351648,"exp":1604355248,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"
brandon(a)cryy.com
"},"source":{"address":"34.94.123.121"}},"signature":"P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4"}}}
Nov 2 21:14:08 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_TIME,
1604351648
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 11
size: 1
slot: {
{
name: auth::token
value:
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjQ4LCJleHAiOjE2MDQzNTUyNDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351648,"exp":1604355248,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"
brandon(a)cryy.com
"},"source":{"address":"34.94.123.121"}},"signature":"P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4"}}}
type: str
}
}
}
On Mon, Nov 2, 2020 at 12:44 PM Brandon Armstead <brandon(a)cryy.com> wrote:
Also to add one more thing, I added a third static
variable into the mix
to test when using the "bad config" just setting server=>auth::name to
"brandon" and introducing the 3rd variable seems to just make kamailio hang
when doing kamcmd htable.dump server <---- (no results returned).
On Mon, Nov 2, 2020 at 12:41 PM Brandon Armstead <brandon(a)cryy.com> wrote:
Daniel,
In short kamcmd does not reflect the value set in $sht(server=>auth
::token)
It alternates between being set and not being set (reflecting in kamcmd
htable.dump
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 11
size: 1
slot: {
{
name: auth::token
value:
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzQ2NzgzLCJleHAiOjE2MDQzNTAzODMsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.aFGWqQg31oNnw10XfZ61Xm5Jncvt7RoNri2ZuDJ6yLQ","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604346783,"exp":1604350383,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"
brandon(a)cryy.com
"},"source":{"address":"34.94.123.121"}},"signature":"aFGWqQg31oNnw10XfZ61Xm5Jncvt7RoNri2ZuDJ6yLQ"}}}
type: str
}
}
}
In the kamailio logs it always shows AUTH_TOKEN_RECEIVED (correctly, with
the correct auth token), kamcmd dump of htable alternates between execution
of this route: htable:expired:server
Exec 1:
auth::time => [timestamp]
Exec 2:
auth::token => token
Exec 3:
auth::time => [timestamp]
So on and so forth, [ kamcmd htable.dump server ] it does not correctly
hold both $sht(server=>auth::time) and $sht(server=>auth::token) like it
should, despite kamailio logs showing the HTTP_AUTH_TOKEN received message
with the correct auth token (100% of the time).
It's almost like there is a race condition when using the modules
http_client_query in both init and expired event route.
When I changed it to the resolved code block above separating the calls
and introducing http_async_client inside htable:expired:server
The result is 100% of the time auth token exists correctly, just like the
logs 100% of the time show the auth token received regardless of
event_route implementation.
So somewhere somehow the problematic config causes the hash table to not
store HTTP_AUTH_TOKEN it receives and logs.
3 Nov
3 Nov
11:59 a.m.
New subject: htable + event_routes + mod-init + htable:expired
Hello,
can you use 'kamctl rpc htable.dump ...' (needs the jsonrpcs module) to
be sure is not some limitation of kamcmd?
Then, you have to be aware that the item is considered expired once the
lifetime elapsed, and it should not show in rpc dump command output,
however, it is removed on-timer cycle and the event_route is executed at
this moment (not when the lifetime elapsed). Practically, the
event_route may be executed later than the moment when corresponding
$sht(...) returns $null.
Based on these considerations, the proper way to refresh the value is to
do it when you need it and $sht(...) returns $null. Or maybe use rtimer
module to refresh it before it expires.
Cheers,
Daniel
On 02.11.20 22:15, Brandon Armstead wrote:
Nov 2 21:13:28 main kamailio[1331]: INFO: <script>:
AUTH_TOKEN_EXPIRED, lets retrieve a new one
Nov 2 21:13:28 main kamailio[1331]: INFO: <script>:
AUTH_TOKEN_RECEIVED,
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjA4LCJleHAiOjE2MDQzNTUyMDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351608,"exp":1604355208,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"brandon@cryy.com
<mailto:brandon@cryy.com>"},"source":{"address":"34.94.123.121"}},"signature":"sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog"}}}
Nov 2 21:13:28 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_TIME,
1604351608
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 11
size: 1
slot: {
{
name: auth::token
value:
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjA4LCJleHAiOjE2MDQzNTUyMDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351608,"exp":1604355208,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"brandon@cryy.com
<mailto:brandon@cryy.com>"},"source":{"address":"34.94.123.121"}},"signature":"sUQImDqDfE-xdA1SQ-7I5TnFMZaPh8WB2c-S-ut1hog"}}}
type: str
}
}
}
Nov 2 21:13:48 main kamailio[1334]: INFO: <script>:
AUTH_TOKEN_EXPIRED, lets retrieve a new one
Nov 2 21:13:48 main kamailio[1334]: INFO: <script>:
AUTH_TOKEN_RECEIVED,
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjI4LCJleHAiOjE2MDQzNTUyMjgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.stW5JzPR-Gz3oVvQEb1wxF7I0GcZ1KjkkQhinHGEivQ","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351628,"exp":1604355228,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"brandon@cryy.com
<mailto:brandon@cryy.com>"},"source":{"address":"34.94.123.121"}},"signature":"stW5JzPR-Gz3oVvQEb1wxF7I0GcZ1KjkkQhinHGEivQ"}}}
Nov 2 21:13:48 main kamailio[1334]: INFO: <script>: AUTH_TOKEN_TIME,
1604351628
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 0
size: 1
slot: {
{
name: auth::time
value: 1604351628
type: int
}
}
}
Nov 2 21:14:08 main kamailio[1331]: INFO: <script>:
AUTH_TOKEN_EXPIRED, lets retrieve a new one
Nov 2 21:14:08 main kamailio[1331]: INFO: <script>:
AUTH_TOKEN_RECEIVED,
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjQ4LCJleHAiOjE2MDQzNTUyNDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351648,"exp":1604355248,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"brandon@cryy.com
<mailto:brandon@cryy.com>"},"source":{"address":"34.94.123.121"}},"signature":"P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4"}}}
Nov 2 21:14:08 main kamailio[1331]: INFO: <script>: AUTH_TOKEN_TIME,
1604351648
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 11
size: 1
slot: {
{
name: auth::token
value:
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzUxNjQ4LCJleHAiOjE2MDQzNTUyNDgsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604351648,"exp":1604355248,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"brandon@cryy.com
<mailto:brandon@cryy.com>"},"source":{"address":"34.94.123.121"}},"signature":"P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4"}}}
type: str
}
}
}
On Mon, Nov 2, 2020 at 12:44 PM Brandon Armstead <brandon(a)cryy.com
<mailto:brandon@cryy.com>> wrote:
Also to add one more thing, I added a third static variable into
the mix to test when using the "bad config" just setting
server=>auth::name to "brandon" and introducing the 3rd variable
seems to just make kamailio hang when doing kamcmd htable.dump
server <---- (no results returned).
On Mon, Nov 2, 2020 at 12:41 PM Brandon Armstead <brandon(a)cryy.com
<mailto:brandon@cryy.com>> wrote:
Daniel,
In short kamcmd does not reflect the value set
in $sht(server=>auth::token)
It alternates between being set and not being set (reflecting
in kamcmd htable.dump
root@main:/etc/kamailio# kamcmd htable.dump server
{
entry: 11
size: 1
slot: {
{
name: auth::token
value:
{"data":{"token":{"token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiJDUllZIiwiaWF0IjoxNjA0MzQ2NzgzLCJleHAiOjE2MDQzNTAzODMsIm1ldGhvZCI6InBvc3Q6YXV0aDp0b2tlbiIsImFjY291bnQiOnsiaWQiOiIxIiwiZmlyc3RuYW1lIjoiVGVzdCIsImxhc3RuYW1lIjoiQXJtc3RlYWQiLCJlbWFpbCI6ImJyYW5kb25AY3J5eS5jb20ifSwic291cmNlIjp7ImFkZHJlc3MiOiIzNC45NC4xMjMuMTIxIn19.aFGWqQg31oNnw10XfZ61Xm5Jncvt7RoNri2ZuDJ6yLQ","header":{"alg":"HS256","typ":"JWT"},"payload":{"iss":"CRYY","iat":1604346783,"exp":1604350383,"method":"post:auth:token","account":{"id":"1","firstname":"Test","lastname":"Armstead","email":"brandon@cryy.com
<mailto:brandon@cryy.com>"},"source":{"address":"34.94.123.121"}},"signature":"aFGWqQg31oNnw10XfZ61Xm5Jncvt7RoNri2ZuDJ6yLQ"}}}
type: str
}
}
}
In the kamailio logs it always shows AUTH_TOKEN_RECEIVED
(correctly, with the correct auth token), kamcmd dump of
htable alternates between execution of this
route: htable:expired:server
Exec 1:
auth::time => [timestamp]
Exec 2:
auth::token => token
Exec 3:
auth::time => [timestamp]
So on and so forth, [ kamcmd htable.dump server ] it does not
correctly hold both $sht(server=>auth::time) and
$sht(server=>auth::token) like it should, despite kamailio
logs showing the HTTP_AUTH_TOKEN received message with the
correct auth token (100% of the time).
It's almost like there is a race condition when using the
modules http_client_query in both init and expired event route.
When I changed it to the resolved code block above separating
the calls and introducing http_async_client
inside htable:expired:server
The result is 100% of the time auth token exists correctly,
just like the logs 100% of the time show the auth token
received regardless of event_route implementation.
So somewhere somehow the problematic config causes the hash
table to not store HTTP_AUTH_TOKEN it receives and logs.
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Funding: https://www.paypal.me/dcmierla
1511
days inactive
1512
days old
1 comments
2 participants
participants (2)
-
Brandon Armstead -
Daniel-Constantin Mierla