>> 1) Set your logging level to INFO (or DEBUG if you like that better).
It is set to info or, all default at this time. >> 2) Wait for the problem to be manifest, that is, a phone is first seen >> and then later not seen on the Active Registrations screen without any >> explanation. As suggested in the past, I am rotating the logs prior to this test. logrotate -f /etc/logrotate.d/sipxchange I also created a tiny script that would help me see the hardware and OS times closer together. # more check-time hwclock --show date When I ran it, the clocks are dead on. # sh check-time Wed 07 Jul 2010 10:57:03 AM CDT -0.260159 seconds Wed Jul 7 10:57:03 CDT 2010 Now trying to replicate the problem. A call came in to one of our 888 lines over the PRI and the problem just happened again. >> 3) Take a snapshot using the Diagnostics -> Snapshot screen. Request >> the time period to be covered by the captured logs to be the present >> back to about 3 hours ago. That should be enough time to capture the >> genesis of the problem. I have a snapshot of the event, 3Hrs back. >> 4) Un-gzip and un-tar the snapshot file in some convenient directory >> on the system. I unpacked it in /new/snapshot I also went to the history menu to see what the last call was but sipx doesn't seem to have logged it. >> 5) cd to var/log/sipxpbx in the unpacked snapshot. Do you mean where I just put the files instead of the sipx log dir. So, this should be /new/snapshot/var/log/sipxbpx then, right? >> 6) Do "merge-logs --ft=[extension] --include-method=register", where >> [extension] is the extension of the phone in question. This extracts >> the REGISTER requests and their responses which have From or To fields >> containing [extension]. I cannot tell which phone the call came in to. However, it might be the following, which I see as the last call which was before the crash by a couple of minutes, yet, still the last call in my mediant syslogs. Jul 7 10:56:14 192.168.1.25 ACK sip:[email protected]:15060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 192.168.1.25;branch=z9hG4bKac1125759519 Max-Forwards: 70 From: "anonymous" <sip:[email protected]>;tag=1c794111170 To: <sip:[email protected];user=phone>;tag=yp94rNU5jX50r Call-ID: [email protected] CSeq: 1 ACK Contact: <sip:[email protected]> Route: <sip:192.168.1.220:5060;lr;sipXecs-CallDest=AL%2CVMR%2CVM;sipXecs-rs=%2Aauth%7E.%2Afrom%7EMWM3OTQxMTExNzA%60.900_ntap%2Aid%7ENDc1MC0xMQ%60%60%215074b93b8f44b88140f45842a9032018;x-sipX-done> Supported: em,timer,replaces,path,early-session,resource-priority Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-Mediant 2000/v.5.60A.027.002 Content-Length: 0 [Time: 09:56:12] So, I'll use this xxxxxx1760 number as the input. Last night, the problem happened calling into a different internal phone so not sure that it is phone/DID specific. Here is the output. Same as before, nothing in merged.xml. # merge-logs --ft=xxxxxx1760 --include-method=register # ls -la total 20008 drwxr-xr-x 2 sipxchange sipxchange 4096 Jul 7 11:27 . drwxr-xr-x 3 sipxchange sipxchange 4096 Jul 7 11:02 .. -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 freeswitch_http.log -rw----r-- 1 sipxchange sipxchange 778 Jul 7 11:02 freeswitch.log -rw-r--r-- 1 sipxchange sipxchange 256 Jul 7 10:47 httpd_access_log -rw-r--r-- 1 sipxchange sipxchange 286 Jul 7 10:47 httpd_error_log -rw-r--r-- 1 sipxchange sipxchange 2768 Jul 7 10:47 httpd_rewrite_log -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 httpd_stderr_log -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 httpd_stdout_log -rw-r--r-- 1 root root 79 Jul 7 11:27 merged.xml -rw-r--r-- 1 sipxchange sipxchange 10727448 Jul 7 11:02 sipregistrar.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipregistrar.xml -rw-r--r-- 1 sipxchange sipxchange 167562 Jul 7 11:02 sipstatus.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipstatus.xml -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 sipXalarms.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipXalarms.xml -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 sipxconfig-audit.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxconfig-audit.xml -rw-r--r-- 1 sipxchange sipxchange 56060 Jul 7 11:02 sipxconfig.log -rw-r--r-- 1 sipxchange sipxchange 96 Jul 7 11:01 sipxconfig-logins.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxconfig-logins.xml -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxconfig.xml -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 sipxivr.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxivr.xml -rw-r--r-- 1 sipxchange sipxchange 218814 Jul 7 11:02 sipxpark.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxpark.xml -rw-r--r-- 1 sipxchange sipxchange 7913389 Jul 7 11:02 sipXproxy.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipXproxy.xml -rw-r--r-- 1 sipxchange sipxchange 342080 Jul 7 11:02 sipxrls.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxrls.xml -rw-r--r-- 1 sipxchange sipxchange 170304 Jul 7 11:02 sipxsaa.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxsaa.xml -rw-r--r-- 1 sipxchange sipxchange 741516 Jul 7 11:02 sipxsupervisor.log -rw-r--r-- 1 root root 79 Jul 7 11:27 sipxsupervisor.xml -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 snapshot.err.log -rw-r--r-- 1 sipxchange sipxchange 0 Jul 7 11:02 snapshot.output.log Cannot proceed to additional steps. Mike >> 7) Do "sipviewer merged.xml &" to run sipviewer and display the >> filtered log information. >> >> 8) Stare at the sipviewer screen to see what's going wrong. What you >> should see is REGISTER requests going from the phone to the proxy to >> the registrar, and responses going back. The requests will come in >> pairs, the first one gets a 401/407 response, the second gets a 200 >> response. Then there will be a gap of several minutes, then the next >> pair, etc. With the default settings, the times at the left are in >> local time, so you should look around the time when the phone was >> unexpectedly not registered. (You can change the times to UTC from >> the pulldown menus.) Each 200 response contains a header "Expires: >> [number]", where [number] is the number of seconds into the fiture >> that the registration has been extended until. The next successful >> REGISTER should complete within that number of seconds of each >> successful REGISTER. >> > As far as I can tell, you are trying to run merge-logs on the live > logs, rather than in the log directory of an unpacked snapshot. > You'll need to fix that: Carry out the parts of (4) and (5) that you > haven't done yet. > > You also haven't run merge-logs with the correct arguments. See step > (6) for what to do. > > After that, you can do (7) and (8) and it might reveal something > interesting. > At the least, you'll have walked through a complete example of how to run > merge-logs and sipviewer, and started learning what sipviewer displays > look like, which will help you with any future problems. > > Dale
_______________________________________________ sipx-users mailing list [email protected] List Archive: http://list.sipfoundry.org/archive/sipx-users Unsubscribe: http://list.sipfoundry.org/mailman/listinfo/sipx-users sipXecs IP PBX -- http://www.sipfoundry.org/
