Odd log messages

General Help
1

Hi guys,

I’ve suddenly started getting lots of repeated logs that look something like these. I have no idea what they mean or what would be causing them… there are no active calls right now. Any ideas as to what these are…???

2021-09-16 20:07:54] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 5de41da546f2833414d8084777475a27@ w.x.y.z:5060
[2021-09-16 20:07:54] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘5de41da546f2833414d8084777475a27@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 42cba38c0e39373b4f4c0ffa578d56c7@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘42cba38c0e39373b4f4c0ffa578d56c7@ w.x.y.z:5060’ to ‘1747cb021b28c2591255285e77a7dfb9@ w.x.y.z:5060’
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 1747cb021b28c2591255285e77a7dfb9@ w.x.y.z:5060
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘1747cb021b28c2591255285e77a7dfb9@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 4975aaa4771ef09b734d112c0423bcfb@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘4975aaa4771ef09b734d112c0423bcfb@ w.x.y.z:5060’ to ‘1a3d62fb215677bb0aa05b7f0b9d1879@ w.x.y.z:5060’
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 1a3d62fb215677bb0aa05b7f0b9d1879@ w.x.y.z:5060
[2021-09-16 20:07:56] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘1a3d62fb215677bb0aa05b7f0b9d1879@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:07:57] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 2fe190f505b140a16a5fa3dd2bc44bff@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:07:57] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘2fe190f505b140a16a5fa3dd2bc44bff@ w.x.y.z:5060’ to ‘0a47f0e756d511270fb6f8645bdf5f4a@ w.x.y.z:5060’
[2021-09-16 20:07:57] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 0a47f0e756d511270fb6f8645bdf5f4a@ w.x.y.z:5060
[2021-09-16 20:07:57] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘0a47f0e756d511270fb6f8645bdf5f4a@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:01] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 1c089a9e36bed7677319a0e95786a5fb@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:01] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘1c089a9e36bed7677319a0e95786a5fb@ w.x.y.z:5060’ to ‘1229d4cd5aae9127692b0d7423924e54@ w.x.y.z:5060’
[2021-09-16 20:08:01] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 1229d4cd5aae9127692b0d7423924e54@ w.x.y.z:5060
[2021-09-16 20:08:01] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘1229d4cd5aae9127692b0d7423924e54@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:01] DEBUG[26236] manager.c: Running action ‘Login’
[2021-09-16 20:08:01] DEBUG[26237] manager.c: Running action ‘Login’
[2021-09-16 20:08:01] DEBUG[26237] manager.c: Running action ‘Command’
[2021-09-16 20:08:01] DEBUG[26237] manager.c: Running action ‘Command’
[2021-09-16 20:08:01] DEBUG[26237] manager.c: Running action ‘Command’
[2021-09-16 20:08:01] DEBUG[26237] manager.c: Running action ‘Command’
[2021-09-16 20:08:03] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 51ecf45878b2990843bffaeb67051549@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:03] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘51ecf45878b2990843bffaeb67051549@ w.x.y.z:5060’ to ‘6575305d6c406c2a15ccda940d8b4579@ w.x.y.z:5060’
[2021-09-16 20:08:03] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 6575305d6c406c2a15ccda940d8b4579@ w.x.y.z:5060
[2021-09-16 20:08:03] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘6575305d6c406c2a15ccda940d8b4579@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:04] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 7ad70d5b05f078693cc7d00731b67179@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:04] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘7ad70d5b05f078693cc7d00731b67179@ w.x.y.z:5060’ to ‘43be7d233c3dafc4052a8a64577884bb@ w.x.y.z:5060’
[2021-09-16 20:08:04] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 43be7d233c3dafc4052a8a64577884bb@ w.x.y.z:5060
[2021-09-16 20:08:04] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘43be7d233c3dafc4052a8a64577884bb@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:11] DEBUG[26236] manager.c: Running action ‘Command’
[2021-09-16 20:08:12] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 29f91b7b235f99273e570929731af115@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:12] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘29f91b7b235f99273e570929731af115@ w.x.y.z:5060’ to ‘3b43491106f6f3fd4207ca2663e53458@ w.x.y.z:5060’
[2021-09-16 20:08:12] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 3b43491106f6f3fd4207ca2663e53458@ w.x.y.z:5060
[2021-09-16 20:08:12] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘3b43491106f6f3fd4207ca2663e53458@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:13] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 3c0a8e730658ad90 - REGISTER (No RTP)
[2021-09-16 20:08:13] DEBUG[31061] chan_sip.c: Store REGISTER’s src-IP:port for call routing.
[2021-09-16 20:08:13] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 64f3c97c7d07249760606f591fe40c33@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:13] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘64f3c97c7d07249760606f591fe40c33@ w.x.y.z:5060’ to ‘4af2e6c42884bc5c79dfec116ff562bc@ w.x.y.z:5060’
[2021-09-16 20:08:13] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 4af2e6c42884bc5c79dfec116ff562bc@ w.x.y.z:5060
[2021-09-16 20:08:13] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘4af2e6c42884bc5c79dfec116ff562bc@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:14] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 284b2a673f911918124fddcd3ba6454e@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:14] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘284b2a673f911918124fddcd3ba6454e@ w.x.y.z:5060’ to ‘06032be77a21bb3e55c7295224ccb76a@ w.x.y.z:5060’
[2021-09-16 20:08:14] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 06032be77a21bb3e55c7295224ccb76a@ w.x.y.z:5060
[2021-09-16 20:08:14] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘06032be77a21bb3e55c7295224ccb76a@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:15] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 38e848e5128b0fa036a224f9218fc53c@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:15] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘38e848e5128b0fa036a224f9218fc53c@ w.x.y.z:5060’ to ‘58cc19d55e64c60625c4427228804836@ w.x.y.z:5060’
[2021-09-16 20:08:15] DEBUG[31061] chan_sip.c: Initializing initreq for method OPTIONS - callid 58cc19d55e64c60625c4427228804836@ w.x.y.z:5060
[2021-09-16 20:08:15] DEBUG[31061] chan_sip.c: Stopping retransmission on ‘58cc19d55e64c60625c4427228804836@ w.x.y.z:5060’ of Request 102: Match Found
[2021-09-16 20:08:20] DEBUG[31061] chan_sip.c: Allocating new SIP dialog for 504d2e710aa6ba441e39e7230dba9beb@ w.x.y.z:5060 - OPTIONS (No RTP)
[2021-09-16 20:08:20] DEBUG[31061] chan_sip.c: SIP call-id changed from ‘504d2e710aa6ba441e39e7230dba9beb@ w.x.y.z:5060’ to ‘235c8f8d7191005351b87f4e6d756fb2@ w.x.y.z:5060’

2

I think I must have turned on some additional logging? I ran asterisk -rvd, but apparently when I exited that session it didn’t turn off the -v or -d extras. I had to stop/start asterisk completely to get the messages reported above to stop.

Still, it begs the questions… what were all of those “call-id changed” lines about when there were no calls happening at all… not internal, not external, not voicemail, nothing. And, what are those “Login” and “Command” entries – no one was logging in and running commands either.

3

The chan_sip module uses the term “call” extremely broadly internally. Sending a qualify request (an OPTIONS) to a device, that’s a call. Sending them a NOTIFY with MWI, that’s a call. It’s essentially a SIP dialog.

As for the Login/Command, those are from AMI. I don’t work on FreePBX, but it probably has stuff logging in automatically and doing stuff.

Generally if you turn on debug level, you’re going to see this kind of stuff, and you’re going to get concerned for no reason.

4

Thanks for the explanation!

5

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.