Random CID behavior on LINE
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 am
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.
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
Navigation
[0] Message Index
[#] Next page