Junos OS

 View Only
last person joined: 2 days ago 

Ask questions and share experiences about Junos OS.
Expand all | Collapse all

Monitoring dynamic subscriber events

  • 1.  Monitoring dynamic subscriber events

    Posted 02-12-2020 07:15

    Hello,

     

    I've been trying to find a way how to monitor the establishment and disconnect events of dynamic subscribers, especially for PPPoE subscribers, and have this sent to an NMS server.

    I can see that dynamic interfaces are being created and then monitored by SNMP, but this doesn't give me any information about which customer connects to or disconnects from our platform.

    Now, the general-authenication-service.log file shows log messages like

    "Feb 12 16:01:13.380952 UserAccess:22723RB63@comsave.nl session-id:1118 state:start ae1.demux0.2:2"

    and

    "Feb 12 16:01:13.677240 UserAccess:xxxx@domain.nl session-id:1118 state:access-granted ae1.demux0.2:2"

    and other message which tell me more about a subscriber.

     

    Would it be possible to have these messages appear in the NMS server somehow?

     

    Beelze



  • 2.  RE: Monitoring dynamic subscriber events

    Posted 02-12-2020 07:32

    I think best option will be to enable accounting duplication and send accounting to NMS. Or you can configure radius server to send such logs to NMS. Unfortunately MX can not send messages when subscribers connect/disconnect via syslog



  • 3.  RE: Monitoring dynamic subscriber events

     
    Posted 02-12-2020 07:45

    Hi,

     

    Other than the accounting information that the MX sends to the AAA servers, another way to forward traceoption logs of general-authentication-service to syslog or NMS server would be as follows:

     

    To view pppoe user/subscribers information, Enable authd traceoptions flagging "only" "user-access" Flag:

    For instance:

     

    set system processes general-authentication-service traceoptions file authd

    set system processes general-authentication-service traceoptions file size 20m

    set system processes general-authentication-service traceoptions file files 10

    set system processes general-authentication-service traceoptions flag user-access

     

     

    For example:  When subscriber attempts a login or logout.

     

    {master}[edit]

    root@re0# run show log authd   

    root@re0 clear-log[37400]: logfile cleared

     UserAccess:karand@test.com session-id:64 state:start xe-9/0/0.demux0.3221225533:601

     UserAccess:karand1@test.com session-id:63 state:start xe-3/2/0.demux0.3221225532:602

    UserAccess:karand1@test.com session-id:63 state:access-granted xe-3/2/0.demux0.3221225532:602

     UserAccess:karand@test.com session-id:64 state:access-granted xe-9/0/0.demux0.3221225533:601

    UserAccess:karand@test.com session-id:60 state:log-out xe-9/0/0.demux0.3221225529:601 reason: ppp lcp-peer-terminate-term-req

    UserAccess:karand1@test.com session-id:59 state:log-out xe-3/2/0.demux0.3221225528:602 reason: ppp lcp-peer-terminate-term-req

     

     

    In case if you require or want subscriber IPAdd as well, flag “address-assignment”:

    set system processes general-authentication-service traceoptions flag address-assignment

     

     

    Now configure  “set system tracing destination-override syslog host x.x.x.x”

     

    This will send traceoptions logs towards your syslog or NMS server.

    This specifies the remote host running the system log process (syslogd), which collects the traces.

    Traces are written to file(s) on the remote host per the syslogd configuration in /etc/syslog.conf.

     

    Here is more info:

    https://www.juniper.net/documentation/en_US/junos/topics/concept/junos-software-tracing-logging-operations-overview.html

     

     

     

     



  • 4.  RE: Monitoring dynamic subscriber events

    Posted 02-13-2020 01:04

    Hi karand,

     

    Great, I guess that's what I need.

    I configured all of that and don't see the traceoptions saved to the local system anymore, so I guess they are being sent to the host I specified.

    Not sure if they are sent to the NMS server, how would I best check that?

     

    And on the NMS server, I'm using LibreNMS at the moment and syslog-ng is running, what would I need to change to the syslog-ng.conf file to parse incoming traceoption logs to files? Because I don't see the files just being created.

    I guess overriding traceoptions is not exactly the same as the standard syslogging in JunOS?

    I believe there needs to be some sort of extra configuration to get this to work.

     

    UPDATE:

     

    The link you posted also contains this explanation:

    "To collect traces, use the local0 facility as the selector in /etc/syslog.conf on the remote host. To separate traces from various processes into different files, include the process name or trace-file name if it is specified at the [edit process-name traceoptions file] hierarchy level, in the Program field in /etc/syslog.conf. If your syslog server supports parsing hostname and program name, then you can separate traces from the various processes."

     

    On the NMS server, when I disable and enable a PPPoE client interface, I can see the standard syslog coming in, but not the overridden traceoptions.

     

    [root@no-reverse-yet syslog-ng]# tcpdump host MXROUTER -i ens192 -v

    tcpdump: listening on ens192, link-type EN10MB (Ethernet), capture size 262144 bytes

    11:19:34.567689 IP (tos 0x0, ttl 62, id 25477, offset 0, flags [none], proto UDP (17), length 182)

        no-reverse-yet.comsave.nl.syslog > no-reverse-yet.comsave.nl.syslog: SYSLOG, length: 154

    Facility daemon (3), Severity info (6)

    Msg: Feb 13 11:18:46 ams-eq4-ar1-customs mib2d[2063]: MIB2D_DLL_UPDATE_MISMATCH: tunnel_delete: Invalid Update Type:IFL ifm_link:41 ifm_type:63 port_type:0

    11:19:37.031165 IP (tos 0x0, ttl 62, id 25593, offset 0, flags [none], proto UDP (17), length 201)

        no-reverse-yet.comsave.nl.syslog > no-reverse-yet.comsave.nl.syslog: SYSLOG, length: 173

    Facility daemon (3), Severity error (3)

    Msg: Feb 13 11:18:49 ams-eq4-ar1-customs bbesmgd[2294]: SMD_PPP_RX_UNKNOWN_PACKET_PROTOCOL: bbe_if_ppp_input: Rx unknown packet protocol 0x8281 code 0x1 on ifl pp0.3221225593

    11:19:37.134269 IP (tos 0x0, ttl 62, id 25619, offset 0, flags [none], proto UDP (17), length 177)

        no-reverse-yet.comsave.nl.syslog > no-reverse-yet.comsave.nl.syslog: SYSLOG, length: 149

    Facility daemon (3), Severity info (6)

    Msg: Feb 13 11:18:49 ams-eq4-ar1-customs rpd[2264]: krt unsolic client: Received IPv6 address fe80::564b:8cff:fe30:30c1 on ifl pp0.3221225593. Flag:0.

     

     

    This is what I want to see:

     

    Feb 13 08:46:42.674958 UserAccess:22723RB63@comsave.nl session-id:1125 state:logout-start ae1.demux0.2:2

    Feb 13 08:46:42.977311 UserAccess:22723RB63@comsave.nl session-id:1125 state:log-out ae1.demux0.2:2 reason: ppp lcp-peer-terminate-term-req

    Feb 13 08:46:58.976899 UserAccess:22723RB63@comsave.nl session-id:1126 state:start ae1.demux0.2:2

    Feb 13 08:46:59.475858 UserAccess:22723RB63@comsave.nl session-id:1126 state:access-granted ae1.demux0.2:2

     

     

    My configuration

    syslog {
        user * {
            any emergency;
        }
        host NMS {
            any any;
        }
        file messages {
            any any;
            inactive: authorization info;
            archive size 1m files 10;
        }
        file interactive-commands {
            interactive-commands any;
        }
        source-address MXROUTER;
    }
    tracing destination-override syslog host NMS
    processes {
        general-authentication-service {
            traceoptions {
                file authd size 10m files 10;
                flag user-access;
                flag address-assignment;
            }
        }
    }
    

     

    Beelze



  • 5.  RE: Monitoring dynamic subscriber events

     
    Posted 02-13-2020 03:43

    Hi beeelzebub,

     

    Once you configure destination-override syslog host, the MX will not write trace logs locally in /var/log.

    This is for certain supported processes/deamon only and authd is one of them.

     

    May i know what is your MX platform and JUNOS version?

    Can you share output of "cat /etc/syslog.conf" from your MX

     

    I used rsyslog server in my lab and here is  tcpdump capture from my rsyslog server:

    tcpdump: listening on ens33, link-type EN10MB (Ethernet), capture size 262144 bytes
    Msg: 9 16:05:11 authd[15903]: UserAccess:karand@test.com session-id:147 state:start xe-9/0/0.demux0.3221225616:601\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: UserAccess:karand1@test.com session-id:148 state:start xe-3/2/0.demux0.3221225617:602\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Received subscriber login request, subscriber-session-id:148\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10005 length 4\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10080 length 17\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10153 length 54\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10169 length 8\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Processing address request in default:tmnl_altbh_sec_ds network 255.255.255.254 mac 00:11:02:00:00:01\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: readSessionEntry\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Processing rule Reserve-Address\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: ************** START-ReserveAddress ******************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: *********************************************************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: IPV6 PREFIX ALLOC begin\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: *************** END-ReserveAddress *******************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: *********************************************************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Done processing rules\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Trying to assign address 10.0.243.9 to subscriber session-id:148\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Received subscriber login request, subscriber-session-id:147\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10005 length 4\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10080 length 17\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10153 length 25\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Decoding attribute 10169 length 8\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Processing address request in default:tmnl_altbh_sec_ds network 255.255.255.254 mac 00:11:01:00:00:01\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: readSessionEntry\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Processing rule Reserve-Address\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: ************** START-ReserveAddress ******************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: *********************************************************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: IPV6 PREFIX ALLOC begin\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: *************** END-ReserveAddress *******************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: *********************************************************\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Done processing rules\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: Trying to assign address 10.232.144.113 to subscriber session-id:147\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: UserAccess:karand1@test.com session-id:148 state:access-granted xe-3/2/0.demux0.3221225617:602\0x0a\0x00
    Msg: 9 16:05:11 authd[15903]: UserAccess:karand@test.com session-id:147 state:access-granted xe-9/0/0.demux0.3221225616:601\0x0a\0x00
    Msg: 9 16:05:16 authd[15903]: Received subscriber logout request session-id:147\0x0a\0x00
    Msg: 9 16:05:16 authd[15903]: subscriberLogout session-id:147\0x0a\0x00
    Msg: 9 16:05:16 authd[15903]: Received subscriber logout request session-id:148\0x0a\0x00
    Msg: 9 16:05:16 authd[15903]: subscriberLogout session-id:148\0x0a\0x00

     

     



  • 6.  RE: Monitoring dynamic subscriber events

    Posted 02-13-2020 04:18

    See outputs below.

    My TCPdump doesn't show me the logs sent with remote tracing.

     

    user@host> start shell    

    % cat /etc/syslog.conf

    *.* /var/log/messages

     

    local7.* /var/log/interactive-commands

     

    *.emerg *

    #%source-address <source address of the Juniper - Loopback>

     

     

    user@host> show version

    Hostname: ams-eq4-ar1-customs

    Model: mx5-t

    Junos: 18.4R2-S3



  • 7.  RE: Monitoring dynamic subscriber events

     
    Posted 02-13-2020 06:48

    Can you add local0 string in the /etc/syslog.conf?

    I haven't tried on MX-5 which is ppc image and I doubt this could be PPC bases platform issue. 

     

    I tested on mx480 and works just fine. Do you by any chance have any non-ppc MX platform (like mx240/mx480) to check? 

    On syslog server, I captured tcpdump the logs as follows:

     

    [root@centos-7-x64-min ~]# tcpdump -nnAs0 -i ens33 host 10.xx.xx.230 (MX IP-ADDERESS)

     

    .9......m4C<135>Feb 13 19:49:59 authd[13910]: UserAccess:karand@l2bsa.com session-id:1 state:start ae0:32-3200
    .9......m4C<135>Feb 13 19:49:59 authd[13910]: UserAccess:karand@l2bsa.com session-id:1 state:start ae0:32-3200
    09:06:03.689362 IP 10.xx.xx.xx.58556 > 10.xx.xx.x.514: SYSLOG local0.debug, length: 110 E...8...?...
    .9......v.M<135>Feb 13 19:50:00 authd[13910]: UserAccess:karand@l2bsa.com session-id:1 state:access-granted ae0:32-3200
    .9......v.M<135>Feb 13 19:50:00 authd[13910]: UserAccess:karand@l2bsa.com session-id:1 state:access-granted ae0:32-3200
    09:06:21.356478 IP 10.xx.xx.xx.58465 > 10.xx.xx.xx.514: SYSLOG local0.debug, length: 105

     

     

     



  • 8.  RE: Monitoring dynamic subscriber events

    Posted 02-13-2020 06:56

    Can you share me the exact string I need to add to the file?

    Do i need to restart any process for it to have effect?

     

    I also tried to capture the packets with your command, but nothing shows up.



  • 9.  RE: Monitoring dynamic subscriber events

     
    Posted 02-13-2020 19:31

    Hi Beeelzebub,

     

    Ran some few test in lab and found that this function seems to be broken in newer release.

    I tested in  junos 18.4R3 and 19.2R1 and didn't work but when i tried in junos 17.4R2-S6 and 16.2R2-S1, it worked just fine.

     

    So, try in JUNOS 17.4R2-S7 or 17.4R2-S9?

    As for function broken in newer release, we'll get this fixed with devolper on upcoming builds.

     

     

     

     

     

     

     



  • 10.  RE: Monitoring dynamic subscriber events

    Posted 02-14-2020 00:12

    Hi Karand,

     

    I tested on two devices with version 18.4R2-S3 and the destination-override syslog statement does not work there.

    Then I tested on a device with a very old version, 14.2R7-S9, and the logs were immediately visible in my NMS server.

    The thing is that we really need 18.4R2-S3 or 18.4R3 because of a IPv6 dual stack pppoe fix that I opened a while ago, but we also need this destination-override syslog statement.

    Can you tell me if there is a work around for this version? Like modifying the syslog file or something.

    Otherwise, a PR might need to be requested.

     

    Beelze



  • 11.  RE: Monitoring dynamic subscriber events

     
    Posted 02-14-2020 00:26

    Hi Beeelzebub,

     

    unfortunately, there is no workaround at present and as I mentioned in my previous post, as for the function that is broken in newer releases, we'll get this fixed for the upcoming newers builds.

     

    You may track PR1489339 which I had logged earlier today with developer to get this fixed in the s/w.  I would suggest to log a case with us as well to scope a fix for you in specfic release, in your required junos.

     

    Nonetheless, thanks for bringing up this issue to our notice.

     

     

     

     

     

     

     

     

     

     



  • 12.  RE: Monitoring dynamic subscriber events

    Posted 02-14-2020 00:38

    Hi Karand,

     

    Thanks for filing the PR so fast!

    I tried searching for the PR at https://prsearch.juniper.net/InfoCenter/index?page=prsearch and I got the following error:

    "It appears you are searching for a PR which is not available. It could be that the PR number is not valid, or that it refers to a PR which has no externally available content. If you have questions on a particular PR which is not providing results, please contact JTAC. You can try another PR id at PR Search"

     

    Beelze



  • 13.  RE: Monitoring dynamic subscriber events

     
    Posted 02-14-2020 00:50
    Hi Beelze,

    Since it's a new PR..the PR is currently under view and will be made public for viewing in couple of days once it's reviewed.

    Regards
    Karan


  • 14.  RE: Monitoring dynamic subscriber events

     
    Posted 02-14-2020 02:34

    Hi Beelze,

     

    In the meanwhile, as a possible workaround you could try the following command (please adjust the file name and syslog server IP address first):

    start shell command "tail -F /var/log/authd.log | logger -h 10.10.10.10 &"

     

    Best regards,

    Sergii

    -------------------------------------------------------------------

    Please accept the solution if your problem is resolved Smiley Happy

    -------------------------------------------------------------------



  • 15.  RE: Monitoring dynamic subscriber events

    Posted 02-14-2020 04:38

    Hi Sergii,

     

    Thanks, this is a nice work-around.

    I just tested it and the outcome is the same as tracing destination-override syslog on older versions.

    It's good enough for now.

     

    Maybe this is outside the scope of this thread, but is it possible to only send logs matching certain keywords?

    If so, how would that be done.

     

    UPDATE:

     

    there you go..

    start shell command "tail -F /var/log/authd | grep --line-buffered 'UserAccess\|address' | logger -h 10.10.10.10 &"

     

    Beelze

     

     



  • 16.  RE: Monitoring dynamic subscriber events

    Posted 04-22-2020 05:04

    Hi Sergii,

     

    I hope you don't mind me following up on this topic.

    While your work-around works perfectly, I was wondering if it's possible to use a different tcp/udp port for sending dynamic syslog messages.

     

    I tried the following, and while it does not complain I see no packets coming in.

     

    start shell command "tail -F /var/log/authd | grep --line-buffered 'UserAccess' | logger -h 62.171.173.47 -P 50514 &"


  • 17.  RE: Monitoring dynamic subscriber events

     
    Posted 04-29-2020 14:29

    Hi Beelze,

     

    It doesn't seem possible - there is no such option:

    root@mx480:/var/home/lab # logger -h
    logger: option requires an argument -- h
    usage (for logging a syslog message): logger [-46Ais] [-f file] [-h host] [-p pri] [-t tag] [message ...]
    usage (for the event creation): logger [-e <event-id>] [-d <daemon-name>] [-a <"attr=value"> list]
    [-p pri] [-l logical-system-name] [message ...]

    I'd also appreciate if you could mark one of posts in this thread as a solution, as your concern seems to have been resolved - either one way or another.

     

    Best regards,

    Sergii

    -------------------------------------------------------------------

    Please accept the solution if your problem is resolved Smiley Happy

    -------------------------------------------------------------------



  • 18.  RE: Monitoring dynamic subscriber events

    Posted 12-07-2020 10:50

    Hi Sergii and Karan,

    How wud be the CPU hits when we configure tracing destination-override or the command below to run in the background? 

    start shell command "tail -F /var/log/authd | grep --line-buffered 'UserAccess' | logger -h 62.171.173.47 -P 50514 &"

    It is not recommended to enable trace options all the time by JTAC because of the resource-intensive process. 


    Best Regard,

    Kijush



    ------------------------------
    Kijush Maharjan
    ------------------------------