#25 NCIDD reports CID instead of HUP

[Anonymous]

Just upgraded from 1.3 to 1.6 (compiled from source). Incoming calls whose caller-ids match a blacklist entry are answered and receive the appropriate outgoing announcement (hangup=3) but are identified in cidcall.log with "CID:" rather than "HUP:".

[Todd Andrews]

Hi Anonymous,

We'll need to see /var/log/ncidd.log run at verbose level 5. At a minimum it should include the lines:

• from Started: through End of startup: inclusive
• from the first RING of the call to when it sends CID: inclusive

Could you also try hangup=1? Sometimes a modem has enough power to do a normal hangup but not hangup=2 or hangup=3.

Send the log as an attachment to me (tandrews@users.sf.net) and John (jlc@users.sf.net) as a private email. Your privacy is assured, however, feel free to obfuscate phone numbers.

[John L. Chmielewski]

I checked hangup in NCID 1.6 using hangup mode 1 and hangup mode 3. Both call log entries were indentified with HUP: instead of CID:

You need to check that ncidd version 1.6 is configured properly. Make sure the phone number is in ncidd.blacklist and that ncidd.conf has any changes you added in version 1.3. Make sure the recording plays before hangup. Try testing with hangup mode 1 first, then hangup mode 3.

Kill off ncidd and do the testing using the following command line after creating the needed T-* files. You do not need to run as root:

ncidd -Dv5 -B T-black -L T-log -c T-call -H1

The command line uses ./T-log in place of /var/log/ncidd.log, ./T-call in place of /var/log/cidcall.log, and ./T-black in place of /etc/ncid/ncidd.blacklist. Testing with the above command should show you where the problem is and what needs to be corrected by reviewing the debug output in the terminal window or in T-log.

If You cannot solve your problem, you need to attach your T-log file to the bug report, or you can email it to Todd and myself instead. You also need to indicate which modem you are using and which operating system.

[Reece]

Oops... looks like I forgot to log in before creating this bug report. I'll try to update this in the next couple of days.

[Reece]

Ok, longer than a couple of days.

The problem is that the code assumes that, after the calls to write(2) transmitting the voice file complete, the message has been sent on the phone line and the modem is ready to accept new commands. In my case the modem is attached via USB and there is deep buffering, so the voice file writes complete almost immediately. The modem does not acknowledge the transmission of the voice message until it's been sent on the phone line, which may be many seconds. Yet the code expects a response within 600 milliseconds (6 * 0.1 seconds).

One fix would be to change the iteration count parameter to initModem() in ncidd.c line 431 from 6 (HANGUPRETRY = 0.6 seconds) to 600 (60.0 seconds). This resolves the problem for hangup messages shorter than 60 seconds.

[John L. Chmielewski]

Please provide information on your modem. Most modems used for NCID are USB. It would also help if you provided the T-log file as indicated in a previous messge, in particular, need to see the results of quering the modem.

HANGUPRETRY is the length of time to wait if HANGUP failed before sending HANGUP again.

The code you should look at starts at line 385 in nciddhangup.c. Maybe sending the file to the modem should be slower.

[Reece]

As I read it, this is the sequence used in nciddhangup.c to give the caller the bad news:

1. Line 408 sends the "Enter Voice Transmit Data State" command.
2. Lines 421:427 sends the voice file to the modem.
3. Line 431 sends the "Exit Voice Transmit Data State" sequence (<dle><etx>).</etx></dle>

The problem has nothing to do with how fast we send the file to the modem. I'm not seeing a data overrun problem; the modem is receiving the data just fine and playing it as expected, and the modem places the line on-hook. The issue is that the call is reported as CID rather than HUP because the initModem() calls after sending the outgoing voice message report timeouts trying to read the command responses (error code 4).

Note that the commands that come after are actually being queued to and acted upon by the modem. But by then the program has long since given up listening for the responses.

The second parameter to function initModem() is the number of attempts it should make to read a response, with a 0.1 second pause before each attempt. The problem comes because hangupCall() is telling initModem() to expect a response to the "Exit Voice Transmit Data State" sequence within 6 attempts (roughly 0.6 seconds), and it reports a response failure after that. However, the modem will not send an "OK" response to this sequence until it has finished playing the message. The CallingDeposit message takes about 10 seconds to play, and in my tests the response arrives after 100 read attempts.

Here's the relevant excerpt of the logfile with verbosity 7 after changing the maximum number of read attempts on line 431 from 6 (HANGUPTRY) to 600:

AT+VTX
000000: 41 54 2b 56 54 58 0d 0a                          AT+VTX..
Modem response: 11 characters in 2 reads:

CONNECT
000000: 0d 0a 43 4f 4e 4e 45 43 54 0d 0a                 ..CONNECT..
Sending file /usr/share/ncid/recordings/CallingDeposit.rmd, to modem in 8192 byte chunks
Sent 79235 bytes to modem for announcement
Sent Modem 4 of 4 characters: 
^P^C
000000: 10 03 0d 0a                                      ....
Modem response: 6 characters in 100 reads:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..

None of the other initModem() timeouts need to be changed because the responses to those commands don't have such lengthy delays. The longest response I saw in my logs is to the ANSCALL command on line 406, which takes 4 read attempts.

The modem is a USR5637 56K Faxmodem, and the computer is an 8-core i7 at 3.40 GHz running Linux Mint 18.1 Serena with KDE. The system was pretty much idle during my tests.

[John L. Chmielewski]

Will test your solution on the various USB modems I use to test. All my modems worked OK without modifications. The USR modem has had various problems working with NCID so thank you for solving this USR problem. Not sure about having a 60 second timeout if the modem is not responding because of an error.

You mis-understood my reason for suggesting a slowdown of data sent to the modem. I am aware the modem can handle the speed and not have a data overrun. I thought if the data data speed was about the same as the length of time for the modem to play the message, it would also solve the problem.

[John L. Chmielewski]

I have modified ncidd to increase the number of read tries to 300 which takes up to 30 seconds. The USR modem is the only modem that waits for the entire message before playing it. The other modems I have that work with ncidd start playing before the entire message is sent. The USR takes 154 read tries to get an OK. A zoom modem takes 22 read tries to get an OK.

Attached is nciddhangup.tar.gz containing a modified nciddhangup.c and nciddhangup.h. The changes remove some extranious code and to sets the read tries to 300 instead of your 600. Please test. The changes will be in the next release (NCID 1.7).

Edited to correct errors and post new code.

[Reece]

The proposed changes don't make sense to me.

The USR modem does not "wait until it receives the entire message before playing it"; playback begins immediately. The modem sends an "OK" response after playback completes, meaning it has played the entire voice file and found the <dle><etx> appended to the end of it. There is no need for another command in the serial stream to get an "OK" response.</etx></dle>

The proposed changes prevent the initModem() call on line 431 from waiting for the "OK" response after the outgoing voice message has played. After the 2-second delay, the program is not "taking 134 tries to hangup", it is taking 134 tries to receive the "OK" response from the voice file playback. Unless the program flushes the input buffer somewhere, the "OK" response to the hangup command is still in the input buffer and the commands and responses will then be out of sync.

Have you actually seen problems with other modems after changing only the try count on line 431? On my system, as soon as the voice file completes I see the program report receiving the "OK", then it sends the hangup which completes within the 6 try limit (usually after 3 tries).

I removed only the extra initModem() calls on lines 432 and 433, leaving my change on line 431 intact. Here is a snippet of the log that results:

Processing hangup request
Begin: Search Blacklist file [18:33:10]
End: Search Blacklist file [18:33:10]
Checked Blacklist for match flag=0 ret=1 nmbrmatch=2
Blacklist Match #00: mycellphone   number: mycellphone    name: mycellphone
Sent Modem 4 of 4 characters: 
AT
Modem response: 6 characters in 1 read:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
Sent Modem 13 of 13 characters: 
AT+FCLASS=8
Modem response: 6 characters in 1 read:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
hangup mode 3: VOICEMODE sent, return code is 0
Sent Modem 12 of 12 characters: 
AT+VGT=128
Modem response: 6 characters in 1 read:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
Sent Modem 17 of 17 characters: 
AT+VSM=128,8000
Modem response: 6 characters in 1 read:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
Sent Modem 10 of 10 characters: 
AT+VLS=1
Modem response: 6 characters in 4 reads:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
Sent Modem 6 of 6 characters: 
ATE0
Modem response: 6 characters in 1 read:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
Sent Modem 8 of 8 characters: 
AT+VTX
Modem response: 11 characters in 2 reads:

CONNECT
000000: 0d 0a 43 4f 4e 4e 45 43 54 0d 0a                 ..CONNECT..
Sending file /usr/share/ncid/recordings/CallingDeposit.rmd, to modem in 8192 byte chunks
Sent 79235 bytes to modem for announcement
Sent Modem 4 of 4 characters: 
^P^C
Modem response: 6 characters in 100 reads:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
off-hook for 2 seconds
Sent Modem 6 of 6 characters: 
ATH0
Modem response: 6 characters in 3 reads:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
hangup mode 3: HANGUP sent, return code is 0
Sent Modem 13 of 13 characters: 
AT+FCLASS=0
Modem response: 6 characters in 1 read:

OK
000000: 0d 0a 4f 4b 0d 0a                                ..OK..
hangup mode 3: DATAMODE sent, return code is 0

[John L. Chmielewski]

My old USR modem does not start playing the file until after it receives <dle><etx>. Determined by watching debug and listening on the phone. Perhaps that is why mine took 134 reads vers 100 reads for yours.</etx></dle>

I was not expecting an OK response to <dle><etx>, my bad.</etx></dle>

Changing my source to look for an OK from sending the <dle><etx> changes the results slightly:</etx></dle>

USRobotics: 154 reads to get <DLE><ETX> OK and 3 reads to get hangup OK

Zoom:  22 reads to get <DLE><ETX> OK and 1 read to get hangup OK

I was in error saying 134 tries to hangup when I should have said 134 reads to get hangup OK

Edited my post above to add the new source. Please review.

Thanks for the quick feedback pointing out my error. Hopefully the code is error free now.

[Reece]

These changes look good to me.

Just being nit-picky for a moment, the Posix definition for the usleep function states that "the useconds argument shall be less than one million." Passing a value equal to or greater than one million may return an error with errno set to EINVAL. While passing 2,000,000 to usleep does work on many operating systems, it may not work on all.

http://pubs.opengroup.org/onlinepubs/009695399/functions/usleep.html

[John L. Chmielewski]

Nit-picky is good. The document you specified is not current. The current POSIX specification considers usleep() obsolete and removed it. The Linux web man page does mention the usleep() 1,000,000 limit: http://man7.org/linux/man-pages/man3/usleep.3.html

I probably should start using nanosleep() at some point.

[John L. Chmielewski]

Fixed in NCID 1.7