CLI duplicate printing

Caller details logger printing duplicate messages in my ASTERISK CLI. how fix this. What is the issue?

Connected to Asterisk 18.10.0~dfsg+~cs6.10.40431411-2 currently running on dms (pid = 15280)
    -- Executing [0112xxxxx@from_external:1] Goto("PJSIP/registrar-00000003", "dmse_IVR,s,1") in new stack
    -- Executing [0112xxxxx@from_external:1] Goto("PJSIP/registrar-00000003", "dmse_IVR,s,1") in new stack
    -- Goto (dmse_IVR,s,1)
    -- Goto (dmse_IVR,s,1)
    -- Executing [s@dmse_IVR:1] Answer("PJSIP/registrar-00000003", "") in new stack
    -- Executing [s@dmse_IVR:1] Answer("PJSIP/registrar-00000003", "") in new stack
       > 0x7f8d3c29f210 -- Strict RTP learning after remote address set to: 172.16.x.x:10594
       > 0x7f8d3c29f210 -- Strict RTP learning after remote address set to: 172.16.x.x:10594
    -- Executing [s@dmse_IVR:2] Set("PJSIP/registrar-00000003", "FILENAME=/path/to/call_log.txt") in new stack
    -- Executing [s@dmse_IVR:2] Set("PJSIP/registrar-00000003", "FILENAME=/path/to/call_log.txt") in new stack
    -- Executing [s@dmse_IVR:3] Set("PJSIP/registrar-00000003", "CALL_DETAILS=2024-02-27 08:41:24 - Caller ID: 770xxxxx, Button Pressed: 2, Unique ID:") in new stack
    -- Executing [s@dmse_IVR:3] Set("PJSIP/registrar-00000003", "CALL_DETAILS=2024-02-27 08:41:24 - Caller ID: 770xxxxx, Button Pressed: 2, Unique ID:") in new stack
    -- Executing [s@dmse_IVR:4] System("PJSIP/registrar-00000003", "echo "2024-02-27 08:41:24 - Caller ID: 770xxxxx, Button Pressed: 2, Unique ID:" >> /path/to/call_log.txt") in new stack
    -- Executing [s@dmse_IVR:4] System("PJSIP/registrar-00000003", "echo "2024-02-27 08:41:24 - Caller ID: 7708xxxxx, Button Pressed: 2, Unique ID:" >> /path/to/call_log.txt") in new stack

Please provide your logger.conf.

This is my logger.conf

;
; Logging Configuration
;
; In this file, you configure logging to files or to
; the syslog system.
;
; "logger reload" at the CLI will reload configuration
; of the logging system.

[general]
console => debug

;
; Customize the display of debug message time stamps
; this example is the ISO 8601 date format (yyyy-mm-dd HH:MM:SS)
;
; see strftime(3) Linux manual for format specifiers.  Note that there is also
; a fractional second parameter which may be used in this field.  Use %1q
; for tenths, %2q for hundredths, etc.
;
;dateformat=%F %T       ; ISO 8601 date format
;dateformat=%F %T.%3q   ; with milliseconds
;
;
; This makes Asterisk write callids to log messages
; (defaults to yes)
;use_callids = no
;
; This appends the hostname to the name of the log files.
;appendhostname = yes
;
; This determines whether or not we log queue events to a file
; (defaults to yes).
;queue_log = no
;
; Determines whether the queue_log always goes to a file, even
; when a realtime backend is present (defaults to no).
;queue_log_to_file = yes
;
; Set the queue_log filename
; (defaults to queue_log)
;queue_log_name = queue_log
;
; When using realtime for the queue log, use GMT for the timestamp
; instead of localtime.  The default of this option is 'no'.
;queue_log_realtime_use_gmt = yes
;
; Log rotation strategy:
; none:  Do not perform any logrotation at all.  You should make
;        very sure to set up some external logrotate mechanism
;        as the asterisk logs can get very large, very quickly.
; sequential:  Rename archived logs in order, such that the newest
;              has the highest sequence number [default].  When
;              exec_after_rotate is set, ${filename} will specify
;              the new archived logfile.
; rotate:  Rotate all the old files, such that the oldest has the
;          highest sequence number [this is the expected behavior
;          for Unix administrators].  When exec_after_rotate is
;          set, ${filename} will specify the original root filename.
; timestamp:  Rename the logfiles using a timestamp instead of a
;             sequence number when "logger rotate" is executed.
;             When exec_after_rotate is set, ${filename} will
;             specify the new archived logfile.
;rotatestrategy = rotate
;
; Run a system command after rotating the files.  This is mainly
; useful for rotatestrategy=rotate. The example allows the last
; two archive files to remain uncompressed, but after that point,
; they are compressed on disk.
;
; exec_after_rotate=gzip -9 ${filename}.2
;
;
; For each file, specify what to log.
;
; For console logging, you set options at start of
; Asterisk with -v for verbose and -d for debug
; See 'asterisk -h' for more information.
; Directory for log files is configures in asterisk.conf
; option astlogdir
;
; All log messages go to a queue serviced by a single thread
; which does all the IO.  This setting controls how big that
; queue can get (and therefore how much memory is allocated)
; before new messages are discarded.
; The default is 1000
;logger_queue_limit = 250
;
; Any custom logging levels you may want to use, which can then
; be sent to logging channels. The maximum number of custom
; levels is 16, but not all of these may be available if modules
; in Asterisk define their own.
;custom_levels = foobar,important,compliance
;
[logfiles]

console => /var/log/asterisk/console.log
;
; Format is:
;
; logger_name => [formatter]levels
;
; The name of the logger dictates not only the name of the logging
; channel, but also its type. Valid types are:
;   - 'console'  - The root console of Asterisk
;   - 'syslog'   - Linux syslog, with facilities specified afterwards with
;                  a period delimiter, e.g., 'syslog.local0'
;   - 'filename' - The name of the log file to create. This is the default
;                  for log channels.
;
; Filenames can either be relative to the standard Asterisk log directory
; (see 'astlogdir' in asterisk.conf), or absolute paths that begin with
; '/'.
;
; An optional formatter can be specified prior to the log levels sent
; to the log channel. The formatter is defined immediately preceeding the
; levels, and is enclosed in square brackets. Valid formatters are:
;   - [default] - The default formatter, this outputs log messages using a
; '/'.
;
; An optional formatter can be specified prior to the log levels sent
; to the log channel. The formatter is defined immediately preceeding the
; levels, and is enclosed in square brackets. Valid formatters are:
;   - [default] - The default formatter, this outputs log messages using a
;                 human readable format.
;   - [plain]   - The plain formatter, this outputs log messages using a
;                 human readable format with the addition of function name
;                 and line number. No color escape codes are ever printed
;                 nor are verbose messages treated specially.
;   - [json]    - Log the output in JSON. Note that JSON formatted log entries,
;                 if specified for a logger type of 'console', will be formatted
;                 per the 'default' formatter for log messages of type VERBOSE.
;                 This is due to the remote consoles interpreting verbosity
;                 outside of the logging subsystem.
;
; Log levels include the following, and are specified in a comma delineated
; list:
;    debug
;    trace
;    notice
;    warning
;    error
;    verbose(<level>)
;    dtmf
;    fax
;    security
;    <customlevel>
;
; Verbose takes an optional argument, in the form of an integer level. The
; verbose level can be set per logfile. Verbose messages with higher levels
; will not be logged to the file.  If the verbose level is not specified, it
; will log verbose messages following the current level of the root console.
;
; Debug has multiple levels like verbose. However, it is a system wide setting
; and cannot be specified per logfile. You specify the debug level elsewhere
; such as the CLI 'core set debug 3', starting Asterisk with '-ddd', or in
; asterisk.conf 'debug=3'.
;
;
;debug => debug
;trace => trace
;security => security
console => notice,warning,error
;console => notice,warning,error,debug
messages => notice,warning,error
;full => notice,warning,error,debug,verbose,dtmf,fax
;
;full-json => [json]debug,verbose,notice,warning,error,dtmf,fax
;
;syslog keyword : This special keyword logs to syslog facility
;
;syslog.local0 => notice,warning,error
;
; A log level defined in 'custom_levels' above
;important.log = important


I’d start by removing this bogus line;

Hello @david551, I removed that line, but not fixed duplicate issue. Are there any other solutions?

It seems that the Asterisk CLI is displaying duplicate messages because the logging statements are being executed twice for each action. This duplication is likely caused by the fact that the same actions are being triggered twice in the dialplan.

In the provided log, we can see that the same actions are executed twice for each step. For example:

-- Executing [0112xxxxx@from_external:1] Goto("PJSIP/registrar-00000003", "dmse_IVR,s,1") in new stack
-- Executing [0112xxxxx@from_external:1] Goto("PJSIP/registrar-00000003", "dmse_IVR,s,1") in new stack

and

-- Executing [s@dmse_IVR:1] Answer("PJSIP/registrar-00000003", "") in new stack
-- Executing [s@dmse_IVR:1] Answer("PJSIP/registrar-00000003", "") in new stack

This indicates that the same instructions are being executed twice in the dialplan
i hope you will get it

Best Regard
Danish Hafeez | QA Assistant
ICTInnovations

On Wednesday 28 February 2024 at 05:45:16, chandimadharmarathne via Asterisk
Community wrote:

This is my logger.conf

[logfiles]

console => /var/log/asterisk/console.log

Try removing (or commenting out) that line and see if your duplicates
disappear.

Antony.


A good conversation is like a miniskirt;
short enough to retain interest,
but long enough to cover the subject.

  • Celeste Headlee

                                                Please reply to the list;
                                                      please *don't* CC me.
    

On Monday 04 March 2024 at 10:15:46, Antony Stone wrote:

console => /var/log/asterisk/console.log

Try removing (or commenting out) that line and see if your duplicates
disappear.

PS: Don’t forget to do a “logger reload” after modifying that file.


I lay awake all night wondering where the sun went, and then it dawned on me.

                                               Please reply to the list;
                                                     please *don't* CC me.

The same channel executing on two threads would be even more broken than getting double logging. The chances that this diagnosis is correct is negligible. Things are likely to break much more badly than logging anomalies if this is really happening.

After I reload the logger, Asterisk CLI show as bellow.


dms*CLI> logger reload
 Asterisk Queue Logger restarted
 Asterisk Queue Logger restarted
dms*CLI>

But problem not solved. How fix it

And, after restart my asterisk, then status show like this

root@dms:/etc/asterisk# systemctl status asterisk
● asterisk.service - Asterisk PBX
     Loaded: loaded (/lib/systemd/system/asterisk.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2024-03-05 08:36:07 +0530; 12s ago
       Docs: man:asterisk(8)
   Main PID: 29741 (asterisk)
      Tasks: 77 (limit: 4558)
     Memory: 44.0M
        CPU: 3.201s
     CGroup: /system.slice/asterisk.service
             ├─29741 /usr/sbin/asterisk -g -f -p -U asterisk
             └─29743 astcanary /var/run/asterisk/alt.asterisk.canary.tweet.tweet.tweet 29741

Mar 05 08:36:04 dms systemd[1]: Starting Asterisk PBX...
Mar 05 08:36:07 dms systemd[1]: Started Asterisk PBX.

Hello, I solved this problem replacing my old logger.conf file as logger.conf
This is code

;
; Logging Configuration
;
; In this file, you configure logging to files or to
; the syslog system.
;
; "logger reload" at the CLI will reload configuration
; of the logging system.

[general]
;
; Customize the display of debug message time stamps
; this example is the ISO 8601 date format (yyyy-mm-dd HH:MM:SS)
;
; see strftime(3) Linux manual for format specifiers.  Note that there is also
; a fractional second parameter which may be used in this field.  Use %1q
; for tenths, %2q for hundredths, etc.
;
;dateformat=%F %T       ; ISO 8601 date format
;dateformat=%F %T.%3q   ; with milliseconds
;
;
; This makes Asterisk write callids to log messages
; (defaults to yes)
;use_callids = no
;
; This appends the hostname to the name of the log files.
;appendhostname = yes
;
; This determines whether or not we log queue events to a file
; (defaults to yes).
;queue_log = no
;
; Determines whether the queue_log always goes to a file, even
; when a realtime backend is present (defaults to no).
;queue_log_to_file = yes
;
; Set the queue_log filename
; (defaults to queue_log)
;queue_log_name = queue_log
;
; When using realtime for the queue log, use GMT for the timestamp
; instead of localtime.  The default of this option is 'no'.
;queue_log_realtime_use_gmt = yes
;
; Log rotation strategy:
; none:  Do not perform any logrotation at all.  You should make
;        very sure to set up some external logrotate mechanism
;        as the asterisk logs can get very large, very quickly.
; sequential:  Rename archived logs in order, such that the newest
;              has the highest sequence number [default].  When
;              exec_after_rotate is set, ${filename} will specify
;              the new archived logfile.
; rotate:  Rotate all the old files, such that the oldest has the
;          highest sequence number [this is the expected behavior
;          for Unix administrators].  When exec_after_rotate is
;          set, ${filename} will specify the original root filename.
; timestamp:  Rename the logfiles using a timestamp instead of a
;             sequence number when "logger rotate" is executed.
;             When exec_after_rotate is set, ${filename} will
;             specify the new archived logfile.
;rotatestrategy = rotate
;
; Run a system command after rotating the files.  This is mainly
; useful for rotatestrategy=rotate. The example allows the last
; two archive files to remain uncompressed, but after that point,
; they are compressed on disk.
;
; exec_after_rotate=gzip -9 ${filename}.2
;
;
; For each file, specify what to log.
;
; For console logging, you set options at start of
; Asterisk with -v for verbose and -d for debug
; See 'asterisk -h' for more information.
;
; Directory for log files is configures in asterisk.conf
; option astlogdir
;
; All log messages go to a queue serviced by a single thread
; which does all the IO.  This setting controls how big that
; queue can get (and therefore how much memory is allocated)
; before new messages are discarded.
; The default is 1000
;logger_queue_limit = 250
;
; Any custom logging levels you may want to use, which can then
; be sent to logging channels. The maximum number of custom
; levels is 16, but not all of these may be available if modules
; in Asterisk define their own.
;custom_levels = foobar,important,compliance
;
[logfiles]
;
; Format is:
;
; logger_name => [formatter]levels
;
; The name of the logger dictates not only the name of the logging
; channel, but also its type. Valid types are:
;   - 'console'  - The root console of Asterisk
;   - 'syslog'   - Linux syslog, with facilities specified afterwards with
;                  a period delimiter, e.g., 'syslog.local0'
;   - 'filename' - The name of the log file to create. This is the default
;                  for log channels.
;
; Filenames can either be relative to the standard Asterisk log directory
; (see 'astlogdir' in asterisk.conf), or absolute paths that begin with
; '/'.
;
; An optional formatter can be specified prior to the log levels sent
; to the log channel. The formatter is defined immediately preceeding the
; levels, and is enclosed in square brackets. Valid formatters are:
;   - [default] - The default formatter, this outputs log messages using a
;                 human readable format.
;   - [plain]   - The plain formatter, this outputs log messages using a
;                 human readable format with the addition of function name
;                 and line number. No color escape codes are ever printed
;                 nor are verbose messages treated specially.
;   - [json]    - Log the output in JSON. Note that JSON formatted log entries,
;                 if specified for a logger type of 'console', will be formatted
;                 per the 'default' formatter for log messages of type VERBOSE.
;                 This is due to the remote consoles interpreting verbosity
;                 outside of the logging subsystem.
;
; Log levels include the following, and are specified in a comma delineated
; list:
;    debug
;    trace
;    notice
;    warning
;    error
;    verbose(<level>)
;    dtmf
;    fax
;    fax
;    security
;    <customlevel>
;
; Verbose takes an optional argument, in the form of an integer level. The
; verbose level can be set per logfile. Verbose messages with higher levels
; will not be logged to the file.  If the verbose level is not specified, it
; will log verbose messages following the current level of the root console.
;
; Debug has multiple levels like verbose. However, it is a system wide setting
; and cannot be specified per logfile. You specify the debug level elsewhere
; such as the CLI 'core set debug 3', starting Asterisk with '-ddd', or in
; asterisk.conf 'debug=3'.
;
; Special level name "*" means all levels, even dynamic levels registered
; by modules after the logger has been initialized (this means that loading
; and unloading modules that create/remove dynamic logger levels will result
; in these levels being included on filenames that have a level name of "*",
; without any need to perform a 'logger reload' or similar operation).
; Note that there is no value in specifying both "*" and specific level names
; for a filename; the "*" level means all levels.  The only exception is if
; you need to specify a specific verbose level. e.g, "verbose(3),*".
;
; We highly recommend that you DO NOT turn on debug mode if you are simply
; running a production system.  Debug mode turns on a LOT of extra messages,
; most of which you are unlikely to understand without an understanding of
; the underlying code.  Do NOT report debug messages as code issues, unless
; you have a specific issue that you are attempting to debug.  They are
; messages for just that -- debugging -- and do not rise to the level of
; something that merit your attention as an Asterisk administrator.  Both
; debug and trace messages are also very verbose and can and do fill up
; logfiles quickly.  This is another reason not to have debug or trace
; modes on a production system unless you are in the process of debugging
; a specific issue.
;
;debug.log => error,warning,notice,verbose,debug
;trace.log => trace
;security.log => security
console => notice,warning,error
;console => notice,warning,error,debug
messages.log => notice,warning,error
;full.log => notice,warning,error,debug,verbose,dtmf,fax
;
;full-json.log => [json]debug,verbose,notice,warning,error,dtmf,fax
;
;syslog keyword : This special keyword logs to syslog facility
;
;syslog.local0 => notice,warning,error
;
; A log level defined in 'custom_levels' above
;important.log = important






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