News:

On Tuesday September 6th the forum will be down for maintenance from 9:30 PM to 11:59 PM PDT

Main Menu

Random CID behavior on LINE

Started by FreeSpeech, January 13, 2012, 07:07:36 PM

Previous topic - Next topic

FreeSpeech

I use the OBI 110 in the US with AT&T as the provider of a local phone line which I connect to the LINE port. I sometimes get CID displayed on my phone. A standard telephone with CID attached in parallel to the OBI always shows the CID. Always. I have checked all of the parameters mentioned in forum responses, CID method is Bell 202, Ring Delay is 5000. I've tried increasing Ring Delay to various values including as high as 10000 to no avail. The behavior doesn't seem to change.

Here's the wierd part: the incoming number never shows up in the Last 10 Calls log, even when it is displayed on my phone. Never. So the OBI is *not* receiving the number but sometimes passes it along to the phone anyway? Go figure!

Stewart

Log into the OBi web interface directly (not via OBiTALK) and report whether Status->Call History shows the calling number for calls that display on your phone, and for calls that do not.  It appears that something is wrong with the Last 10 log.

Possibly, your caller ID problem is related to sending to the PHONE port, rather than reading from the LINE port; Call History should show whether this is the case.

FreeSpeech

Thanks for responding!

I looked at the Call History using the Web interface rather than OBiTalk. There are no numbers listed for any incoming calls, including the ones for which the CID worked correctly.

Stewart

Quote from: FreeSpeech on January 14, 2012, 05:45:03 AMI looked at the Call History using the Web interface rather than OBiTalk. There are no numbers listed for any incoming calls, including the ones for which the CID worked correctly.
Assuming that the calls were otherwise logged normally (only the Peer Name and Peer Number fields are blank), sorry but I have no idea what could possibly be happening.  AFAIK, there is no way for caller ID to be passed to the PHONE port, other than the OBi reading and decoding it from the LINE port, then re-encoding it to send on the PHONE port, several seconds later.

I just tested a call to the LINE port of my OBi running 1.3.0 (Build: 2586); Peer Number did correctly appear in Call History.

Was the PHONE port ringing delayed, as expected, by RingDelay?  What else can you say about your logs?  Are the phone numbers correct on outgoing calls?  On incoming calls to SP1 or SP2?  On incoming calls on the LINE port that are bridged to SP1 or SP2?

If there are no other clues, perhaps syslog will shed some light.

FreeSpeech


>> I looked at the Call History using the Web interface rather than OBiTalk. There are no numbers listed for any incoming calls, including the ones for which the CID worked correctly.

> Assuming that the calls were otherwise logged normally (only the Peer Name and Peer Number fields are blank), sorry but I have no idea what could possibly be happening.  AFAIK, there is no way for caller ID to be passed to the PHONE port, other than the OBi reading and decoding it from the LINE port, then re-encoding it to send on the PHONE port, several seconds later.

Yes, the calls were otherwise logged normally. However, I think I have some idea how I manage to get CID sometimes. When I adjust the Ring Delay using OBiTalk, the first test call I make displays the CID correctly, then no more do until I adjust it again. When I set up syslog, I saw that the OBi 110 is doing stuff in response to the reconfiguration when the call goes through with correct CID. Perhaps because it is in some kind of a pass-through mode while processing the configuration change? Then, when it has processed the change perhaps it goes back into a mode where it tries to parse and process the CID information and cannot?

> I just tested a call to the LINE port of my OBi running 1.3.0 (Build: 2586); Peer Number did correctly appear in Call History.

I've got 1.3.0 (Build 2669).

> Was the PHONE port ringing delayed, as expected, by RingDelay?  What else can you say about your logs?  > Are the phone numbers correct on outgoing calls?  On incoming calls to SP1 or SP2?  On incoming calls on the LINE port that are bridged to SP1 or SP2?

This is hard to say for sure, but I think that in the cases where CID was shown correctly there was no delay.

In other ways the logs seem fine. I haven't had any incoming GV calls on SP1 but outgoing calls seem normal. I'm not doing any other bridging between the lines, so I can't comment on that.

> If there are no other clues, perhaps syslog will shed some light.

I've copied the log that was created while the call went through that did show CID correctly. As far as I can make out it did not see the call at all, but was busy rebooting and handling GV and such.

<7> PNNCOMM:Receive sync req, set auto config
   192.168.2.10   14/01 13:48:21.868   
<149> We will check OBt config in 10 s   192.168.2.10   14/01 13:48:21.869   
<150> PROV: Start to download files ...
   192.168.2.10   14/01 13:48:31.872   
<7> TCP:Connect OK(HTTP GET)28
   192.168.2.10   14/01 13:48:31.965   
<150> PROV: Update Config Now, itsp:0...
   192.168.2.10   14/01 13:48:32.368   
<136> XML_parse_prov 0
   192.168.2.10   14/01 13:48:32.388   
<142> PARAM Cache Write Back(256 bytes)    192.168.2.10   14/01 13:48:32.434   
<142> PARAM Cache Write Back(256 bytes)    192.168.2.10   14/01 13:48:32.441   
<145> Reboot is scheduled in 1 seconds
   192.168.2.10   14/01 13:48:32.443   
<149> We will check OBt config in 3600 s   192.168.2.10   14/01 13:48:32.444   
<0> Reboot checking.....   192.168.2.10   14/01 13:48:33.442   
<0> Final Cleanup before reboot....
   192.168.2.10   14/01 13:48:33.444   
<7> XMPP:State changed from: 14 to:19
   192.168.2.10   14/01 13:48:33.446   
<144> Goodbye! Reboot Now. (reason: 6)
   192.168.2.10   14/01 13:48:34.442   
<6> ==== Networking is ready ====
   192.168.2.10   14/01 13:48:41.490   
<0> IP Address= 192.168.2.10    192.168.2.10   14/01 13:48:41.492   
<0> Gateway   = 192.168.2.1    192.168.2.10   14/01 13:48:41.494   
<0> Netmask   = 255.255.255.0    192.168.2.10   14/01 13:48:41.496   
<3> SYSTEM REBOOTED (Reason: 6, lifecycle: 73)
   192.168.2.10   14/01 13:48:41.498   
<173> ZT: CustomID 1
   192.168.2.10   14/01 13:48:41.505   
<0> SLIC_init ...   192.168.2.10   14/01 13:48:41.535   
<0> Reset SLIC...   192.168.2.10   14/01 13:48:41.537   
<150> Setup Provisioning for system start! 1800
   192.168.2.10   14/01 13:48:41.548   
<150> Setup Provisioning2 for system start! 2400
   192.168.2.10   14/01 13:48:41.550   
<0> SLIC & DAA is initialized   192.168.2.10   14/01 13:48:43.194   
<6> Start Main Service Now   192.168.2.10   14/01 13:48:45.257   
<7> Voice Main
   192.168.2.10   14/01 13:48:45.260   
<7> [CPT] --- FXS s/w tone generator (ringback) ---
   192.168.2.10   14/01 13:48:45.264   
<7> BASESSL:load cert:5
   192.168.2.10   14/01 13:48:45.377   
<7> BASESSL:Load certificate ok
   192.168.2.10   14/01 13:48:45.385   
<7> XMPP:State changed from: 0 to:1
   192.168.2.10   14/01 13:48:45.394   
<7> GTT:Init xmpp node ok
   192.168.2.10   14/01 13:48:45.395   
<7> XMPP:State changed from: 1 to:2
   192.168.2.10   14/01 13:48:45.397   
<7> XMPP:Invalid cfg use for xmpp
   192.168.2.10   14/01 13:48:45.399   
<7> GTT:xmpp not configured
   192.168.2.10   14/01 13:48:45.401   
<7> [SLIC]:Slic#0 ON HOOK
   192.168.2.10   14/01 13:48:46.616   
<7> [DAA]: FXO ring on
   192.168.2.10   14/01 13:48:46.726   
<7> XMPP:State changed from: 2 to:3
   192.168.2.10   14/01 13:48:50.391   
<7> TCP:Connect OK(xmpp)14
   192.168.2.10   14/01 13:48:50.407   
<7> XMPP:State changed from: 3 to:4
   192.168.2.10   14/01 13:48:50.410   
<7> XMPP:Enable reqto
   192.168.2.10   14/01 13:48:50.412   
<7> XMPP_PROC:TLS required!
   192.168.2.10   14/01 13:48:50.429   
<7> XMPP:State changed from: 4 to:5
   192.168.2.10   14/01 13:48:50.446   
<7> TCS:ssl connected
   192.168.2.10   14/01 13:48:51.166   
<7> XMPP:State changed from: 5 to:6
   192.168.2.10   14/01 13:48:51.168   
<7> XMPP:Enable reqto
   192.168.2.10   14/01 13:48:51.170   
<7> XMPP:new stream restarted from remote, old state=1
   192.168.2.10   14/01 13:48:51.189   
<7> XMPP:State changed from: 6 to:8
   192.168.2.10   14/01 13:48:51.193   
<7> XMPP:State changed from: 8 to:9
   192.168.2.10   14/01 13:48:51.249   
<7> XMPP:Enable reqto
   192.168.2.10   14/01 13:48:51.253   
<7> XMPP:new stream restarted from remote, old state=1
   192.168.2.10   14/01 13:48:51.273   
<7> XMPP:State changed from: 9 to:10
   192.168.2.10   14/01 13:48:51.275   
<7> XMPP:State changed from: 10 to:11
   192.168.2.10   14/01 13:48:51.295   
<7> XMPP:State changed from: 11 to:12
   192.168.2.10   14/01 13:48:51.297   
<7> XMPP:State changed from: 12 to:13
   192.168.2.10   14/01 13:48:51.324   
<7> XMPP:State changed from: 13 to:14
   192.168.2.10   14/01 13:48:51.326   
<7> XMPP:Disable reqto
   192.168.2.10   14/01 13:48:51.328   
<7> GTT:xmpp service up
   192.168.2.10   14/01 13:48:51.335   
<7> [DAA]: FXO ring on
   192.168.2.10   14/01 13:48:52.098   
<7> [CPT] --- FXS s/w tone generator (sit_1) ---
   192.168.2.10   14/01 13:48:53.377   
<7> GTALKVM:Checking VM....
   192.168.2.10   14/01 13:48:56.329   
<7> GTALKVM:state changed from 0 to 1
   192.168.2.10   14/01 13:48:56.331   
<7> TCP:Connect OK(lhttpc)18
   192.168.2.10   14/01 13:48:56.864   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:48:56.865   
<7> TC:ssl connected
   192.168.2.10   14/01 13:48:57.582   
<7> LHC:Response OK
   192.168.2.10   14/01 13:48:57.716   
<7> LHC:set Retrying:www.google.com, 1
   192.168.2.10   14/01 13:48:57.880   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:48:58.380   
<7> TCP:Connect OK(lhttpc)19
   192.168.2.10   14/01 13:48:58.415   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:48:58.416   
<7> TC:ssl connected
   192.168.2.10   14/01 13:48:59.126   
<7> LHC:set Retrying:www.google.com, 1
   192.168.2.10   14/01 13:48:59.285   
<150> PROV: Start to download files ...
   192.168.2.10   14/01 13:48:59.551   
<147> PROV: Invalid server name, Skipped
   192.168.2.10   14/01 13:48:59.553   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:48:59.781   
<7> TCP:Connect OK(lhttpc)20
   192.168.2.10   14/01 13:48:59.816   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:48:59.818   
<7> TC:ssl connected
   192.168.2.10   14/01 13:49:00.564   
<7> LHC:set Retrying:www.google.com, 1
   192.168.2.10   14/01 13:49:00.709   
<7> [CPT] tone compression done - 15563 !!
   192.168.2.10   14/01 13:49:00.826   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:49:01.202   
<7> TCP:Connect OK(lhttpc)21
   192.168.2.10   14/01 13:49:01.237   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:49:01.239   
<7> TC:ssl connected
   192.168.2.10   14/01 13:49:01.950   
<7> LHC:set Retrying:www.google.com, 1
   192.168.2.10   14/01 13:49:02.080   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:49:02.571   
<7> TCP:Connect OK(lhttpc)22
   192.168.2.10   14/01 13:49:02.606   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:49:02.608   
<7> TC:ssl connected
   192.168.2.10   14/01 13:49:03.318   
<7> LHC:Server name not matching:plus.google.com/settings/?authuser=0 vs www.google.com
   192.168.2.10   14/01 13:49:03.479   
<7> LHC:Invalid location
   192.168.2.10   14/01 13:49:03.480   
<7> GGSVC:Invalid response
   192.168.2.10   14/01 13:49:03.482   
<7> GTALKVM:Google login failed!
   192.168.2.10   14/01 13:49:03.484   
<7> GTALKVM:state changed from 1 to 2
   192.168.2.10   14/01 13:49:03.486   
<150> PROV: Start to download files ...
   192.168.2.10   14/01 13:49:05.555   
<7> TCP:Connect OK(HTTP GET)24
   192.168.2.10   14/01 13:49:05.701   
<150> PROV: Update Config Now, itsp:0...
   192.168.2.10   14/01 13:49:06.157   
<136> XML_parse_prov 0
   192.168.2.10   14/01 13:49:06.179   
<150> Same version:  Skipped (2)   192.168.2.10   14/01 13:49:06.227   
<150> PROV: Start to download files ...
   192.168.2.10   14/01 13:49:06.231   
<7> TCP:Connect OK(HTTP GET)26
   192.168.2.10   14/01 13:49:06.311   
<150> PROV: Update Config Now, itsp:0...
   192.168.2.10   14/01 13:49:06.540   
<136> XML_parse_prov 0
   192.168.2.10   14/01 13:49:06.545   
<150> Same version:  Skipped (2)   192.168.2.10   14/01 13:49:06.550   
<149> We will check OBt config in 3600 s   192.168.2.10   14/01 13:49:06.553   
<7> [PR] prompt transcoding done!!
   192.168.2.10   14/01 13:51:06.087   
<7> GTALKVM:Checking VM....
   192.168.2.10   14/01 13:52:03.525   
<7> GTALKVM:state changed from 2 to 1
   192.168.2.10   14/01 13:52:03.527   
<7> TCP:Connect OK(lhttpc)28
   192.168.2.10   14/01 13:52:03.558   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:52:03.560   
<7> TC:ssl connected
   192.168.2.10   14/01 13:52:04.270   
<7> LHC:Server name not matching:accounts.google.com/MigrateCookie?continue=https%3A%2F%2Fwww.google.com%2Faccounts%2FManageAccount&service=grandcentral&uberauth=APh-3FwUXbZ-9bgD489YMHXLQMUJoidd93Zgb5_sxT5uneUWcud8PpO4VZdQpCabZpS0NDQYeLvUL5iM74R3vBwVzj_AU   192.168.2.10   14/01 13:52:04.425   
<7> LHC:Invalid location
   192.168.2.10   14/01 13:52:04.426   
<7> GGSVC:Invalid response
   192.168.2.10   14/01 13:52:04.427   
<7> GTALKVM:Google login failed!
   192.168.2.10   14/01 13:52:04.427   
<7> GTALKVM:state changed from 1 to 2
   192.168.2.10   14/01 13:52:04.428   
<7> GTALKVM:Checking VM....
   192.168.2.10   14/01 13:58:04.522   
<7> GTALKVM:state changed from 2 to 1
   192.168.2.10   14/01 13:58:04.523   
<7> TCP:Connect OK(lhttpc)30
   192.168.2.10   14/01 13:58:05.036   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:58:05.038   
<7> TC:ssl connected
   192.168.2.10   14/01 13:58:05.749   
<7> LHC:set Retrying:www.google.com, 0
   192.168.2.10   14/01 13:58:05.982   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:58:06.079   
<7> TCP:Connect OK(lhttpc)31
   192.168.2.10   14/01 13:58:06.102   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:58:06.104   
<7> TC:ssl connected
   192.168.2.10   14/01 13:58:06.811   
<7> LHC:set Retrying:www.google.com, 0
   192.168.2.10   14/01 13:58:06.920   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:58:07.021   
<7> TCP:Connect OK(lhttpc)32
   192.168.2.10   14/01 13:58:07.039   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:58:07.041   
<7> TC:ssl connected
   192.168.2.10   14/01 13:58:07.752   
<7> LHC:set Retrying:www.google.com, 0
   192.168.2.10   14/01 13:58:07.852   
<7> LHC:retrying...www.google.com
   192.168.2.10   14/01 13:58:07.950   
<7> TCP:Connect OK(lhttpc)33
   192.168.2.10   14/01 13:58:07.969   
<7> Trying to connect ssl
   192.168.2.10   14/01 13:58:07.970   
<7> TC:ssl connected
   192.168.2.10   14/01 13:58:08.680   
<7> LHC:Server name not matching:plus.google.com/settings/?authuser=0 vs www.google.com
   192.168.2.10   14/01 13:58:08.820   
<7> LHC:Invalid location
   192.168.2.10   14/01 13:58:08.822   
<7> GGSVC:Invalid response
   192.168.2.10   14/01 13:58:08.824   
<7> GTALKVM:Google login failed!
   192.168.2.10   14/01 13:58:08.826   
<7> GTALKVM:state changed from 1 to 2
   192.168.2.10   14/01 13:58:08.827   

jimates

When I adjust the Ring Delay using OBiTalk, the first test call I make displays the CID correctly, then no more do until I adjust it again.

If you are making changes on the device itself, it sounds like provisioning needs to be turned off so Obitalk doesn't reset your changes.

FreeSpeech

Disabling provisioning doesn't seem to change anything.

RonR

Quote from: FreeSpeech on January 14, 2012, 01:08:13 PM
Disabling provisioning doesn't seem to change anything.

Assuming you set the following in the OBi directly and then rebooted:

System Management -> Auto Provisioning -> ITSP Provisioning -> Method : Disabled
System Management -> Auto Provisioning -> OBiTALK Provisioning -> Method : Disabled

Did you then double-check in the OBi directly that RingDelay is set to the desired value?

The OBi only uses the settings that are present in the OBi itself.

FreeSpeech

I was very careful about disabling provisioning and then making the changes on the device itself and then checking that they were in fact made properly (no use of OBiTalk).

However, I was incorrect about turning off provisioning not making any difference. Now that OBiTalk provisioning is turned off, I cannot get the CID to work after I update the configuration in OBiTalk (this was a separate experiment after getting no results working on the OBi itself as describe above). This seems to lend support to the idea that the CID was working because the OBi was busy doing something else (such as getting the configuration from OBiTalk) and therefore didn't attempt to process the CID itself. Does anyone know if the OBi actually does something like that when it is busy?

I haven't had a chance to verify that the OBi is now less busy after an update from OBiTalk by looking at syslog, but I'll have a look.

My problem seems to have some similarity to a problem that Ricardo in Brazil is having. Stewart was trying to help him also...

http://www.obitalk.com/forum/index.php?topic=1996.0

FreeSpeech

Additional info: I tried an incoming call on Google Voice and the number showed up properly in the Call History and on the phone.

RevKev

QuoteNow that OBiTalk provisioning is turned off, I cannot get the CID to work after I update the configuration in OBiTalk

If you have provisioning disabled, nothing you do on OBiTalk will have any effect.

FreeSpeech

Now I want to enable OBiTalk autoprovisioning again, but I can't find the original value of the ConfigURL parameter. The default value seems to be Disabled.

RonR

Quote from: FreeSpeech on January 14, 2012, 04:04:32 PM
Now I want to enable OBiTalk autoprovisioning again, but I can't find the original value of the ConfigURL parameter. The default value seems to be Disabled.

Checking the Default box always puts the original/default value back.

Stewart

At this point I believe that caller ID is not being read from the LINE port at all; the times it appeared to work was when the bypass relay was de-energized, i.e. in bypass.

So, why is this happening?  There is credible evidence that it's related to a firmware "upgrade", but it must be something fairly subtle, otherwise there would be many more complaints!

Possibly, it only fails under certain timing or noise conditions or is sensitive to ringing characteristics.  Do you have any possible source of noise on the POTS, e.g. DSL, alarm system, fax machine, multi-line phones with an intercom function, etc?

An interesting test would be to connect the LINE port to a different source, e.g. another ATA, or a line at a friend's or neighbor's.

If that's difficult, you could use the OBi itself.  Temporarily set the LINE port to route to the AA.  Run a cord from LINE port to PHONE port.  Call into the SP1 service, which should ring the PHONE port.  The LINE port should then answer and you should hear the AA.  Then, hang up and see whether Call History shows a valid caller ID on the incoming call to the LINE port.

If the LINE port can get caller ID from another source, we can try adjusting the ring detection parameters or a DSL filter.  If not, we can try a factory reset and reconfigure (in case of a corrupted config), or try reverting to older firmware.

FreeSpeech

Quote from: Stewart on January 15, 2012, 09:22:15 AM
If that's difficult, you could use the OBi itself.  Temporarily set the LINE port to route to the AA.  Run a cord from LINE port to PHONE port.  Call into the SP1 service, which should ring the PHONE port.  The LINE port should then answer and you should hear the AA.  Then, hang up and see whether Call History shows a valid caller ID on the incoming call to the LINE port.

If the LINE port can get caller ID from another source, we can try adjusting the ring detection parameters or a DSL filter.  If not, we can try a factory reset and reconfigure (in case of a corrupted config), or try reverting to older firmware.

I did the experiment you suggested (connecting LINE to PHONE and setting LINE to forward to the AA), and after I dialed in to SP1 and heard the AA the call did show up in the Call History correctly (twice actually, once on SP1 and also on LINE1). So it seems to be a problem with the OBi recognizing CID, perhaps due to noise on the line. I do not have DSL on the line, but I do have an alarm system tied in to it.

More information: I tried connecting an old BellSouth CID device I had lying around to the phone line and it failed to recognize the CID. However, a newer Panasonic cordless phone does correctly recognize the CID when connected directly to the phone line. Thus, it seems that the signal on my phone line may be marginal or for some other reason not is detected by the old CID device or the OBi but *is* detected by the Panasonic phone!

Other information: I did have DSL on this line some time ago (like a year) but I now use a cable modem. I wonder if putting a DSL filter on the line could do some good?  I'll give it a try and post the result.

FreeSpeech

Stewart: Adding a DLS filter to the line made no difference. Can you suggest possible changes to the ring detection parameters?

FreeSpeech

I called AT&T and told them about the problem. They told me that if any device recognizes the CID then the problem must be with the devices that don't. The tech told me that they had never heard of a situation in which the CID was recognized by some devices but not others due to noise or other problems on the line. I told them that I thought it very odd that my old Bellsouth CID device and the OBi should both have a problem at the same time, just by coincidence.

RonR

When you were setting RingDelay to larger values, were you verifying that the values you were setting were actually displayed in the OBi itself and were still in the OBi itself after several failed tests?

FreeSpeech

Yes, I did check and I've rerun the experiment and I'm quite sure that the parameter was set properly.