Guest User!

You are not Sophos Staff.

Thread Info
  • State Not Answered
  • Replies 10 replies
  • Subscribers 0 subscribers
  • Views 1981 views
  • Users 0 members are here
Options
Suggested

[7.380] Accounting reporting page does not load

BarryG
I was having problems with accounting not working in v7.305, as well as a runaway file problem in /tmp/netacc_sql.cache. Some people here recommended a wipe, reinstall, restore, which I have done, with the 7.380 beta ISO.

After restoring my config, the accounting page was loading.

Now, after less than 24 hours, the accounting page is no longer loading.

If I have 'top' running, I see that confd.plx and postgres alternately max out the CPU for about 3 minutes after I try to view the page, but the page never loads (it does ask me once if I want abort or keep waiting; I say keep waiting).

I have 768MB RAM, only 543MB is used according to 'free' (668MB used including buffers/cache), and only 10MB swap.

CPU is a PIII 800MHz, and is only 3% used (by Snort) except when using webmin.

Disk space is fine.

Connection is 4mbits down, 500kbits up, with P2P programs running most of the time (at about 30kbits each way).

I'm not using SMTP, POP3, HTTP, IM, P2P, or VOIP features, just PF, IPS, and occasionally SOCKS.

Thanks,
Barry
Parents Reply Children
  • 0 in reply to BarryG
    FWIW, I just ran an Executive Report... it loaded fairly quickly, and shows 1.7GB transferred today.

    Barry
  • 0 in reply to BarryG
    Upgraded to 7.385... accounting page now loads after  15-20secs.
    However, I've had my PC off for a few days, so the P2P traffic is absent.

    When I try to do a report for the last 7 days, it fails to load, and asks if I want to keep waiting (which doesn't help).

    Going to another part of webmin, and back to accounting now fails to load again, and I see that postgres is chewing up CPU time in 'top' for several minutes.

    I waited for postgres to finish, and am able to get into the report again.

    I also notice that 'reverse-dns.plx' uses a LOT of CPU... is it trying to resolve ALL of the hosts in the report, instead of the ones on the current page (1-20)??


    So, when there's little traffic to report on, the reporting works OK, but when there's lots (of p2p) traffic to report on, it fails.

    I'll have our new 7.305 box in production in a few weeks; I hope it won't have the same problems.

    Thanks,
    Barry
  • 0 in reply to BarryG
    Hi Barry,
    the name resolution always works together with the pager. If you're seeing a report containing 20 hosts, those 20 will be resolved plus the next 20 in the row to reduce waiting times if you use the pager.
    As for the call run times, when you trigger a reporting call you can see this in /tmp/confd-debug.log. The lines you need to look out for are  starting with "using new call" and "call execution runtime". Please check this for calls which work and calls which don't.

    Cheers,
     andreas
  • 0 in reply to andreas

    As for the call run times, when you trigger a reporting call you can see this in /tmp/confd-debug.log. The lines you need to look out for are  starting with "using new call" and "call execution runtime". Please check this for calls which work and calls which don't.


    OK... I'm not able to successfully get a daily report now, as I've had the P2P stuff going for several days now, but here's what the log shows when I try: 

    [3775] [index.plx] [barry (1.2.3.4)] [freeze] info: id="3100" severity="info" sys="System" sub="confd" name="freeze" client="index.plx" facility="webadmin" user="barry" srcip="1.2.3.4"

    [3775] [index.plx] [barry (1.2.3.4)] [thaw] info: id="3100" severity="info" sys="System" sub="confd" name="thaw" client="index.plx" facility="webadmin" user="barry" srcip="1.2.3.4"

    using new call Astaro::Reporting::NetAccounting::TopClients (68a504e391026335dae47a95374c6910)

    [3796] [audld.plx] new username=system ip=127.0.0.1

    [3796] [audld.plx] [system (127.0.0.1)] [new] info: id="3106" severity="info" sys="System" sub="confd" name="authentication successful" client="audld.plx" facility="system" user="system" srcip="127.0.0.1"

    [3796] [audld.plx] wrote session jnaijZmkLRJuNakNBgqG to disk

    [3796] write_sigusr1(add,[3796])

    [3796] [audld.plx] [system (127.0.0.1)] [logout] info: id="3100" severity="info" sys="System" sub="confd" name="closing session jnaijZmkLRJuNakNBgqG: logout" client="audld.plx" facility="system" user="system" srcip="127.0.0.1"

    DESTROY [3796] write_sigusr1(del,[3796])

    [3797] [audld.plx] new username=system ip=127.0.0.1

    [3797] [audld.plx] [system (127.0.0.1)] [new] info: id="3106" severity="info" sys="System" sub="confd" name="authentication successful" client="audld.plx" facility="system" user="system" srcip="127.0.0.1"

    [3797] [audld.plx] wrote session NhtMYxjnagcdFDxOVmeE to disk

    [3797] write_sigusr1(add,[3797])

    [3797] [audld.plx] [system (127.0.0.1)] [logout] info: id="3100" severity="info" sys="System" sub="confd" name="closing session NhtMYxjnagcdFDxOVmeE: logout" client="audld.plx" facility="system" user="system" srcip="127.0.0.1"

    DESTROY [3797] write_sigusr1(del,[3797])

    [3804] [dns-resolver.plx] new username=system ip=127.0.0.1

    [3804] [dns-resolver.plx] [system (127.0.0.1)] [new] info: id="3106" severity="info" sys="System" sub="confd" name="authentication successful" client="dns-resolver.plx" facility="system" user="system" srcip="127.0.0.1"

    [3804] [dns-resolver.plx] wrote session dQHosVLdFScPqYSLYfAc to disk

    [3804] write_sigusr1(add,[3804])

    [3804] [dns-resolver.plx] [system (127.0.0.1)] [logout] info: id="3100" severity="info" sys="System" sub="confd" name="closing session dQHosVLdFScPqYSLYfAc: logout" client="dns-resolver.plx" facility="system" user="system" srcip="127.0.0.1"

    DESTROY [3804] write_sigusr1(del,[3804])

    sql call (db: 'reporting'): 'SELECT ip2country(ip_saddr) as src_country,int2ip(ip_saddr) as src_ip,transform_common(CAST(sum(flow_count) AS BIGINT)) as cnt_flow_str,sum(flow_count) as cnt_flow_int,transform_SI(CAST(sum(raw_in_pktlen+raw_out_pktlen) AS BIGINT),1) as sum_tra_total_str,sum(raw_in_pktlen+raw_out_pktlen) as sum_tra_total_int,transform_common(CAST(sum(raw_in_pktcount+raw_out_pktcount) AS BIGINT)) as sum_pktcount_str,sum(raw_in_pktcount+raw_out_pktcount) as sum_pktcount_int FROM accounting_data WHERE dayabs = 733426 GROUP BY ip_saddr ORDER BY sum_tra_total_int DESC'

    call execution runtime: 85.721249 seconds

    [3824] [dns-resolver.plx] new username=system ip=127.0.0.1

    [3824] [dns-resolver.plx] [system (127.0.0.1)] [new] info: id="3106" severity="info" sys="System" sub="confd" name="authentication successful" client="dns-resolver.plx" facility="system" user="system" srcip="127.0.0.1"

    [3824] [dns-resolver.plx] wrote session CWNBXslMosnGsZFAHdvk to disk

    [3824] write_sigusr1(add,[3824])

    [3824] [dns-resolver.plx] [system (127.0.0.1)] [logout] info: id="3100" severity="info" sys="System" sub="confd" name="closing session CWNBXslMosnGsZFAHdvk: logout" client="dns-resolver.plx" facility="system" user="system" srcip="127.0.0.1"

    DESTROY [3824] write_sigusr1(del,[3824])

    

    [3862] [auisys.plx] new username=system ip=127.0.0.1

    [3862] [auisys.plx] [system (127.0.0.1)] [new] info: id="3106" severity="info" sys="System" sub="confd" name="authentication successful" client="auisys.plx" facility="system" user="system" srcip="127.0.0.1"

    [3862] [auisys.plx] wrote session ldDleMxJOhzzdiyfaLAe to disk

    [3862] write_sigusr1(add,[3862])

    [3862] [auisys.plx] [system (127.0.0.1)] [logout] info: id="3100" severity="info" sys="System" sub="confd" name="closing session ldDleMxJOhzzdiyfaLAe: logout" client="auisys.plx" facility="system" user="system" srcip="127.0.0.1"

    DESTROY [3862] write_sigusr1(del,[3862])

    [3868] [dns-resolver.plx] new username=system ip=127.0.0.1

    [3868] [dns-resolver.plx] [system (127.0.0.1)] [new] info: id="3106" severity="info" sys="System" sub="confd" name="authentication successful" client="dns-resolver.plx" facility="system" user="system" srcip="127.0.0.1"

    [3868] [dns-resolver.plx] wrote session sjhuMOtvQduNuJsUNBGf to disk

    [3868] write_sigusr1(add,[3868])

    [3868] [dns-resolver.plx] [system (127.0.0.1)] [logout] info: id="3100" severity="info" sys="System" sub="confd" name="closing session sjhuMOtvQduNuJsUNBGf: logout" client="dns-resolver.plx" facility="system" user="system" srcip="127.0.0.1"

    DESTROY [3868] write_sigusr1(del,[3868])

    resolver pager (limit: 39 offset: 0 results: 40)

    ip addresses waiting for resolution: 33 (max: 0 per run, 0 = no limit)

    regular pager (limit: 19 offset: 0 results: 20)

    waiting for the resolver to fill the cache (5 seconds)

    ip addresses waiting for resolution: 0 (max: 0 per run, 0 = no limit)

    DESTROY [3775] write_sigusr1(del,[3775])

    [3775] [index.plx] wrote session WwvvXalvPfDLORDGRyvq to disk


    This is from when I hit the reporting page to about two minutes after. The page never loaded in the browser.

    Version is currently 7.385.

    Thanks,
    Barry
  • 0 in reply to BarryG
    From the backend side, everything looks fine. A call runtime of 85 seconds is already 3/4 of those 2 minutes spent just by searching through the network accounting database, so it's not the name resolution which is the culprit.

    Just to get a feeling for what dimensions we're speaking of, can you please run a  

    for I in `seq 733425 733429`; do psql -U reporting reporting -c "SELECT count(*) as count_$I from accounting_data WHERE dayabs = $I"; done

    from the command line? Just to see what amount of data you have gathered during the past days. Hardware-wise you're running at the very edge of what is reasonable - 800 MHz is what even our smallest appliance can offer. Unfortunately, all the frills we've been adding over time are more and more demanding to the underlying hardware, especially the dynamic reporting which depends on decent I/O and CPU to be responsive. A runtime of 85 seconds is not much if the data is fed into the executive report email, but if you're sitting in front of the machine and wait for it it is a lot.

    Cheers,
     andreas
  • 0 in reply to andreas
    Hi, sorry I missed this earlier.
    Here's the output:

    count_733425 
    --------------
                0
    (1 row)

     count_733426 
    --------------
                0
    (1 row)

     count_733427 
    --------------
                0
    (1 row)

     count_733428 
    --------------
                0
    (1 row)

     count_733429 
    --------------
                0
    (1 row)
  • 0 in reply to BarryG
    I have it deleting accounting data after 1 week, so I'm guessing I need to change the seq #'s , but to what I'm not sure.

    Barry
  • 0 in reply to BarryG
    I see now that the # is the day since year 0 [:P]

    Here's the current data:

     count_733429 
    --------------
                0
    (1 row)

     count_733430 
    --------------
           254582
    (1 row)

     count_733431 
    --------------
           257615
    (1 row)

     count_733432 
    --------------
           262796
    (1 row)

     count_733433 
    --------------
           254577
    (1 row)

     count_733434 
    --------------
           253084
    (1 row)

     count_733435 
    --------------
           197147
    (1 row)

     count_733436 
    --------------
           206968
    (1 row)

     count_733437 
    --------------
           225790
    (1 row)

     count_733438 
    --------------
            10313
    (1 row)


    Thanks,
    Barry