Description
Enabled json logging engine, with the following setup:
- kam cmd line params:
--log-engine=json:Mp
- prefix:
log_prefix=", \"callid\": \"$ci\",\"srcip\": \"$si\", \"ts\": $TV(Sn), \"method\": \"$rm\", \"mt\": $mt, \"ua\": \"$(ua{s.escape.common})\", \"cseq\": \"$hdr(CSeq)\", \"status\": $rs "
- another prefix (same result):
log_prefix=", \"callid\": \"$ci\", \"ts\": $TV(Sn) "
What I see that certain json lines are truncated, for example
- one line is interrupted by another json entry
- one line starts "truncated"
Troubleshooting
What I can observe is that seems to happens always with same "kind" of line, usually internal logs, which don't have callid etc.
Log Messages
The following first 3 lines are ok, then the latest is corrupted:
{ "time": "2025-04-04T15:51:44.448427533Z", "idx": 193, "pid": 200, "level": "DEBUG", "module": "core", "file": "core/receive.c", "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
{ "time": "2025-04-04T15:51:44.448682606Z", "idx": 194, "pid": 201, "level": "DEBUG", "module": "core", "file": "core/receive.c", "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
{ "time": "2025-04-04T15:52:14.448279053Z", "idx": 195, "pid": 202, "level": "DEBUG", "module": "core", "file": "core/receive.c", "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
{ "time": "2025-04-04T15:52:14.448505797Z", "idx": 196, "pid": 203, "level": "DEBUG", "module": "core", "file": "core/receive.c"{ "time": "2025-04-04T15:52:14.448508084Z", "idx": 195, "pid": 202, "level": "DEBUG", "module": "core", "file": "core/parser/msg, "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
or (notice 2nd line or 5th one)
{ "time": "2025-04-04T16:13:33.789641936Z", "idx": 221, "pid": 228, "level": "DEBUG", "module": "core", "file": "core/receive.c"{ "time": "2025-04-04T16:13:33.789642978Z", "idx": 222, "pid": 229, "level": "DEBUG", "module": "core", "file": "core/xavp.c", ", "line": 265, "function": "ksr_evrt_pre_routing", "callid": "5715efe40e9b7721-264@127.0.0.1", "ts": 1743783213.789640 , "message": "event route core:pre-routing not defined" }
line": 630, "function": "xavp_destroy_list", "callid": "5715efe40e9b7720-264@127.0.0.1", "ts": 1743783213.789527 , "message": "destroying xavp list (nil)" }
{ "time": "2025-04-04T16:13:33.789646470Z", "idx": 222, "pid": 229, "level": "DEBUG", "module": "core", "file": "core/xavp.c", "line": 630, "function": "xavp_destroy_list", "callid": "5715efe40e9b7720-264@127.0.0.1", "ts": 1743783213.789527 , "message": "destroying xavp list (nil)" }
{ "time": "2025-04-04T16:13:33.789648201Z", "idx": 221, "pid": 228, "level": "DEBUG", "module": "tm", "file": "t_lookup.c", "line": 1579, "function": "t_check_msg", "callid": "5715efe40e9b7721-264@127.0.0.1", "ts": 1743783213.789640 , "message": "msg (0x7f{ "time": "2025-04-04T16:13:33.789649346Z", "idx": 222, "pid": 229, "level": "DEBUG", "module": "core", "file": "core/receive.c"8f7a693c50) id=2/228 global id=1/228 T start=0xffffffffffffffff" }
, "line": 637, "function": "receive_msg", "callid": "5715efe40e9b7720-264@127.0.0.1", "ts": 1743783213.789527 , "message": "cleaning up" }
{ "time": "2025-04-04T16:13:33.789652839Z", "idx": 221, "pid": 228, "level": "DEBUG", "module": "tm", "file": "t_lookup.c", "line": 1424, "function": "t_reply_matching", "callid": "5715efe40e9b7721-264@127.0.0.1", "ts": 1743783213.789640 , "message": "t_reply_matching: hash 26404 label 0 branch 0" }
Additional Information
- Kamailio Version - output of
kamailio -v
6.0.1
happens also with 5.8.x
Debian noble, docker container
—
Reply to this email directly, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.
Message ID: <kamailio/kamailio/issues/4203@github.com>
Description
Enabled json logging engine, with the following setup:
- kam cmd line params:
--log-engine=json:Mp
- prefix:
log_prefix=", \"callid\": \"$ci\",\"srcip\": \"$si\", \"ts\": $TV(Sn), \"method\": \"$rm\", \"mt\": $mt, \"ua\": \"$(ua{s.escape.common})\", \"cseq\": \"$hdr(CSeq)\", \"status\": $rs "
- another prefix (same result):
log_prefix=", \"callid\": \"$ci\", \"ts\": $TV(Sn) "
What I see that certain json lines are truncated, for example
- one line is interrupted by another json entry
- one line starts "truncated"
Troubleshooting
What I can observe is that seems to happens always with same "kind" of line, usually internal logs, which don't have callid etc.
Log Messages
The following first 3 lines are ok, then the latest is corrupted:
{ "time": "2025-04-04T15:51:44.448427533Z", "idx": 193, "pid": 200, "level": "DEBUG", "module": "core", "file": "core/receive.c", "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
{ "time": "2025-04-04T15:51:44.448682606Z", "idx": 194, "pid": 201, "level": "DEBUG", "module": "core", "file": "core/receive.c", "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
{ "time": "2025-04-04T15:52:14.448279053Z", "idx": 195, "pid": 202, "level": "DEBUG", "module": "core", "file": "core/receive.c", "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
{ "time": "2025-04-04T15:52:14.448505797Z", "idx": 196, "pid": 203, "level": "DEBUG", "module": "core", "file": "core/receive.c"{ "time": "2025-04-04T15:52:14.448508084Z", "idx": 195, "pid": 202, "level": "DEBUG", "module": "core", "file": "core/parser/msg, "line": 128, "function": "sip_check_fline", "message": "first line indicates a SIP reply" }
or (notice 2nd line or 5th one)
{ "time": "2025-04-04T16:13:33.789641936Z", "idx": 221, "pid": 228, "level": "DEBUG", "module": "core", "file": "core/receive.c"{ "time": "2025-04-04T16:13:33.789642978Z", "idx": 222, "pid": 229, "level": "DEBUG", "module": "core", "file": "core/xavp.c", ", "line": 265, "function": "ksr_evrt_pre_routing", "callid": "5715efe40e9b7721-264@127.0.0.1", "ts": 1743783213.789640 , "message": "event route core:pre-routing not defined" }
line": 630, "function": "xavp_destroy_list", "callid": "5715efe40e9b7720-264@127.0.0.1", "ts": 1743783213.789527 , "message": "destroying xavp list (nil)" }
{ "time": "2025-04-04T16:13:33.789646470Z", "idx": 222, "pid": 229, "level": "DEBUG", "module": "core", "file": "core/xavp.c", "line": 630, "function": "xavp_destroy_list", "callid": "5715efe40e9b7720-264@127.0.0.1", "ts": 1743783213.789527 , "message": "destroying xavp list (nil)" }
{ "time": "2025-04-04T16:13:33.789648201Z", "idx": 221, "pid": 228, "level": "DEBUG", "module": "tm", "file": "t_lookup.c", "line": 1579, "function": "t_check_msg", "callid": "5715efe40e9b7721-264@127.0.0.1", "ts": 1743783213.789640 , "message": "msg (0x7f{ "time": "2025-04-04T16:13:33.789649346Z", "idx": 222, "pid": 229, "level": "DEBUG", "module": "core", "file": "core/receive.c"8f7a693c50) id=2/228 global id=1/228 T start=0xffffffffffffffff" }
, "line": 637, "function": "receive_msg", "callid": "5715efe40e9b7720-264@127.0.0.1", "ts": 1743783213.789527 , "message": "cleaning up" }
{ "time": "2025-04-04T16:13:33.789652839Z", "idx": 221, "pid": 228, "level": "DEBUG", "module": "tm", "file": "t_lookup.c", "line": 1424, "function": "t_reply_matching", "callid": "5715efe40e9b7721-264@127.0.0.1", "ts": 1743783213.789640 , "message": "t_reply_matching: hash 26404 label 0 branch 0" }
Additional Information
- Kamailio Version - output of
kamailio -v
6.0.1
happens also with 5.8.x
Debian noble, docker container
—
Reply to this email directly, view it on GitHub, or unsubscribe.
You are receiving this because you are subscribed to this thread.
Message ID: <kamailio/kamailio/issues/4203@github.com>