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 "},"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 "},"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 "},"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 "},"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 "},"source":{"address":"34.94.123.121"}},"signature":"P52y8GIkL2FEeT51WbYicjIdjdWp-1FXpIRPLHFmlw4"}}}
type: str
}
}
}
On Mon, Nov 2, 2020 at 12:44 PM Brandon Armstead 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@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 "},"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.
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@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@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.
-
Brandon Armstead -
Daniel-Constantin Mierla