Menu

Slow "Add-Alias" NCIDpop question

Help
nospam
2015-05-04
2015-05-11
  • nospam

    nospam - 2015-05-04

    I'm running NCIDpop v.0.10.6.0 on OS X v.10.10.3 and NCIDD on a rasPI 1.0.3.6a-ns32. The cidcall.log file is 4400 bytes in size with approx. 530 lines in it.

    My question is that it now takes about 1-2 minutes to add a new alias via NCIDpop. Is that what other users are finding?

    I haven't tried starting a new log file yet I'm just thinking that 530 lines isn't a particularly large file to process. I've found that occasionally ncidd starts generating cidcall.log.new.new... files which slows the adding aliases down but that's easily remedied.

     
  • Chris Lenderman

    Chris Lenderman - 2015-05-05

    Hi,

    Adding aliases should be nearly instantaneous. Upon clicking on a name in the call (or message) log, NCIDpop does a request to the server to see if an alias exists; if not, the option to "add alias" appears. Adding an alias results in a command to the server, which should also be instantaneous. From there, you are presented with the option to update log files with the new alias.

    Sounds like the problem exists with a slowly functioning server or a slow connection to the server.

     
  • Todd Andrews

    Todd Andrews - 2015-05-05

    Hi nospam,

    You mention the cidcall.log.new.new files you're seeing.

    When NCIDpop asks, "Would you like to apply aliases to all call logs?", choosing "All Logs" could definitely result in more processing time needed based on 1) the number of cidcall.log files and 2) the size of each one. ncidd waits until all cidcall.log files get updated.

    If everything is running correctly, there should be no .new files when the "add alias" step completes. The presence of .new files means something went wrong, and NCIDpop should display a message about the problem.

    If you answer the NCIDpop prompt by choosing, "Just Current Log", you should experience the nearly instantaneous update that Chris is describing.

    To troubleshoot this, you could try stopping ncidd and restart in debug mode with at least verbose level 3:

    sudo ncidd -Dv3
    

    Add an alias through NCIDpop and watch the output from ncidd. Maybe you'll notice where delays are occurring.

    Note to John: ncidd version 1.0.3.6a-ns32 is one I created just for nospam based on this post.

     
  • nospam

    nospam - 2015-05-05

    I think the .new files are appearing when I update the alias and receive a call at the same time. The .new files seem to appear at random intervals so I can't give you more detail yet as to when they happen. I have been running ncidd in Verbose level: 3 unfortunatly my logs of the previous problems were lost after reboot.

    Is there anything in particular I should look for in the logs?

     
    • Todd Andrews

      Todd Andrews - 2015-05-05

      Hi nospam,

      Is there anything in particular I should look for in the logs?

      Unfortunately not because the issue at hand is the amount of processing time being taken to add an alias and we don't know yet exactly which step is experiencing the slow down. Looking at past logs won't help because there's no indication in a log as to how long something takes to complete. You have to be watching the debug activity in real time.

      Start adding an alias in NCIDpop, then immediately start watching the ncidd debug activity.

      When you experience the slow down, how did you answer the NCIDpop prompt, "Would you like to apply aliases to all call logs?"

       
  • nospam

    nospam - 2015-05-05

    Here is an excerpt from the last time it did something weird with the log files. I manually created a backup of the log file from the shell prompt.

    sudo cp /var/log/cidcall.log /var/log/cidcall.log.2015-04-27

    Everything seemed ok then on May 5th it started creating and leaving the .new files.
    The log file contains:(actual phone numbers and an alias are asterisked out)

    REQ: alias add "--*&&SPAM" "NAMEDEP&&OUT-OF-AREA"
    /usr/bin/ncidutil --multi "/etc/ncid/ncidd.blacklist /etc/ncid/ncidd.whitelist" "/etc/ncid/ncidd.alias" Alias add "
    --&&SPAM" "NAMEDEP&&OUT-OF-AREA" 2>&1
    402 Start of data showing status of handled request
    RESP: Done.
    411 End of response
    REQ: RELOAD
    Received Signal 1: Hangup
    Reloading alias, blacklist, and whitelist files: 05/01/2015 14:04:20
    Processed alias file: /etc/ncid/ncidd.alias
    Alias Table:
    Number of Entries: 145
    Processed blacklist file: /etc/ncid/ncidd.blacklist
    Blacklist Table:
    Number of Entries: 1
    Processed whitelist file: /etc/ncid/ncidd.whitelist
    Whitelist Table:
    Number of Entries: 0
    400 Start of data requiring OK
    INFO: Received Signal 1: Hangup
    INFO: Reloading alias, blacklist, and whitelist files: 05/01/2015 14:04:20
    INFO: Processed alias file: /etc/ncid/ncidd.alias
    INFO: Alias Table:
    INFO: Number of Entries: 145
    INFO: Processed blacklist file: /etc/ncid/ncidd.blacklist
    INFO: Blacklist Table:
    INFO: Number of Entries: 1
    INFO: Processed whitelist file: /etc/ncid/ncidd.whitelist
    INFO: Whitelist Table:
    INFO: Number of Entries: 0
    410 End of data
    REQ: INFO *&&OUT-OF-AREA
    403 Start of data defining permitted requests
    INFO: alias NOALIAS
    INFO: neither
    411 End of response
    REQ: UPDATES
    /usr/bin/cidupdate -a /etc/ncid/ncidd.alias -c /var/log/cidcall.log --multi < /dev/null 2>&1
    401 Start of data requiring ACCEPT or REJECT
    INFO: There were 3 changes to /var/log/cidcall.log
    INFO: There was 1 change to /var/log/cidcall.log.2015-04-27
    INFO: There were no changes to /var/log/cidcall.log.2015-04-27.new
    INFO: There were no changes to /var/log/cidcall.log.new
    INFO:
    INFO: 1 Changed "
    ***
    " to "****" for * 3 times
    INFO: 1 Changed "OUT-OF-AREA" to "SPAM" for * 1 time
    410 End of data
    REQ: INFO
    *&&OUT-OF-AREA
    403 Start of data defining permitted requests
    INFO: alias NOALIAS
    INFO: neither
    411 End of response

    The worst case was when I noticed it was creating multiple .new files
    cidcall.log.new.new.new.new.new.new.new.new.new.new.new.new.new
    It looks to me that the script will parse any log file that begins with "cidcall.log" and the .new files aren't being deleted properly for whatever reason - maybe a busy processor not executing all commands in the stack?

     
  • Todd Andrews

    Todd Andrews - 2015-05-05

    Hi nospam,

    It looks to me that the script will parse any log file that begins with "cidcall.log"

    That is exactly right. The more cidcall.log files it finds when you say "All Logs," the longer it will take for the "add alias" process to complete.

    and the .new files aren't being deleted properly for whatever reason - maybe a busy processor not executing all commands in the stack?

    The primary way I can see this happening is if something interrupts the RPi while it's updating all the files. For example, hitting <CTRL-C> while ncidd is running in debug mode, or maybe something triggers the RPi to reboot.

    Another way this could happen would be if there is some bug in the code. EXCEPT for the long delay you're experiencing, is the "add alias" working OK?

     
  • Todd Andrews

    Todd Andrews - 2015-05-05

    I think the .new files are appearing when I update the alias and receive a call at the same time.

    This could be another way. I think it will be best if we figure out what's causing the slow down first and then we can tackle the leftover .new files.

     
  • nospam

    nospam - 2015-05-06

    FYI I made a backup of the cidcall.log file and deleted everything but the last 40 lines. The add-alias now works in under 5 seconds. I'm guessing something in the way the code parses the file is getting bogged down on the wee little Pi. Hmm 40 lines 5 seconds, 500 lines 120 seconds...maybe to many other tasks running in the background?

     
  • Todd Andrews

    Todd Andrews - 2015-05-08

    Hi nospam,

    maybe to many other tasks running in the background?

    That is certainly possible.

    I haven't seen responses to the slow down related questions I asked above or to the troubleshooting steps I provided -- does this mean you tried them but saw no evidence of slow down? And therefore the most reasonable conclusion you've come to is the slow down has to do with other background tasks? It's OK if this is the case, I'm just wondering.

    Regarding the other issue of multiple .new files, we're looking into making changes to improve the "clean up" routines that would remove the .new files in unusual termination circumstances.

     
  • nospam

    nospam - 2015-05-08

    Sorry I missed answering your questions. Here's my responses:

    1. is the "add alias" working OK?
      Yes, just very slow with a larger log file. The only problem I've run into was having an alias that was too long causing ncidd to crash/be unresponsive until I manually changed the alias log file and rebooted.

    2. Re- Debug mode
      Haven't tried that yet. The rasPi is running headless and is also running Motion v.3.2.12 at the same time.

    3.When you experience the slow down, how did you answer the NCIDpop prompt, "Would you like to apply aliases to all call logs?"
    I answered Yes to apply to all logs.

     
    • BTodCox

      BTodCox - 2015-05-08

      Motion is usually quite a cpu hog on an RPi. What is the performance of add-alias with Motion not running?

       
    • Todd Andrews

      Todd Andrews - 2015-05-09

      Hi nospam,

      1. Do you happen to still have details on the ncidd crash with the long alias line? There's a possibility this could have left an orphaned .new file, too.

      2. Hold off on doing these steps. I was thinking about your slow down issue quite a bit today and I'm going to add some debug code that should help us pinpoint the problem. I'll try to complete this in the next few days and provide you modified program(s) with instructions.

      3. The size of the logs you reported above seem to be only for the current one, cidcall.log. Since the alias update is being applied to all logs, you'll have to take the size of all of them into account when considering the total time it takes to add an alias.

      Could you send me and John by private email your file ncidd.alias? Send as an attachment to: tandrews@users.sf.net and jlc@users.sf.net.

       
  • nospam

    nospam - 2015-05-10

    Hi Todd, the ncidd.alias file is only 228 lines long (8671 bytes). I would want to clean up the alias file to remove private numbers before sending it by PE.

    The only odd part is that some ncidd.alias entries are with quotes for the phone numbers but most are without quotes e.g.


    alias NAME * = "test1" if "12345678910"
    alias NAME * = "test2" if 12345678911

    It looks like two different parts of code are writing to the alias file. "Update Alias" is adding the quotes as far as I can tell.

    The other thing that I like to do is tag SPAMMER numbers with the alias "SPAM"


    alias NAME * = "SPAM" if 18033392763

    So my alias file has about 100 "SPAM" tags for different numbers. In my blacklist file I block any name with "SPAM" in it. My only entry in the blacklist file is the word SPAM.

    /##############
    /# Auto Added #
    /##############

    SPAM


    My whitelist file is the stock version with no added entries.

    The reason why I do this is that I find ncidd likes to tag many numbers as "OUT-OF-AREA" (even numbers with my local area code) and the ncid client on my iPad only shows the caller name as "OUT-OF-AREA" instead of the full caller ID or number. This may be due to the fact I'm running the USR5637 modem. Adding the alias "SPAM" is a nice way to quickly flag SPAM calls without having to click on anything in the ncidd client call list.

    With regards to Motion I tried "Update Alias" with motion on and off. The test cidcall.log file has 58 entries (4873 bytes) and I modified the very last entry phone number that appears only once in the log. I timed it roughly from when I select the "OK" button from the prompt "Please Enter The Alias Name for Phone Number" to the time the "Accept or Reject" popup appears.

    Motion OFF - 14 seconds
    Motion ON - 20 seconds

    Yes there is a penalty for multitasking on the Pi.

    The ncidd crash logs are long gone sorry.

    Generally ncidd is doing its job and blocks the SPAM numbers on the first ring (sweet). I could never get the "answer blacklisted callers with fax" working properly as ncidd crashes and stops working after the first time it answers the blacklisted caller with a fax. I assumed this was a problem with the USR modem and never pursued it beyond the first few crashes.

     
  • nospam

    nospam - 2015-05-11

    I spoke to soon. I don't know what I did but ncidd is now hanging up on every caller. Don't have a clue why other than I ran several update aliases.

     

Log in to post a comment.