forum.bitel.ru
http://forum.bitel.ru/

[5.2] Проблема при авторизации [РЕШЕНО]
http://forum.bitel.ru/viewtopic.php?f=22&t=7195		 Страница 1 из 1
Автор:  [S] [ 05 сен 2012, 10:59 ]
Заголовок сообщения:  [5.2] Проблема при авторизации [РЕШЕНО]
Код:
  Клиент: вер. 5.2 сборка 1024 от 17.08.2012 19:28:07
    os: Windows XP; java: Java HotSpot(TM) Client VM, v.1.7.0
    ВНИМАНИЕ: Спецификация версии 1.7 не рекомендуется
  Сервер: вер. 5.2 сборка 1282 от 17.08.2012 17:41:32
    os: CentOS 6.3; Linux; java: Java HotSpot(TM) Client VM, v.1.7.0
    ВНИМАНИЕ: Спецификация версии 1.7 не рекомендуется

  card вер. 5.2 сборка 182 от 06.08.2012 11:20:38
  dialup вер. 5.2 сборка 348 от 06.08.2012 11:20:46


Описание: авторизация на основе POST-запросов через Mikrotik HotSpot-сервер. Договора создаются автоматически на основании карточных логин\паролей из модуля карточки.

Проблема: после перезагрузки RADIUS-сервера (stop\start или перезагрузки всей ОС), первый пользователь, желающий авторизоваться, видит ошибку, которую передает Mikrotik HotSpot - "RADIUS-сервер не доступен" или "не верные логин\пароль", в мониторе соединений ошибки отсутствуют.
Пользователь перезагружает страницу, повторно отправляя POST-запрос на Mikrotik и успешно авторизовывается. Последующие пользователи постоянно видят ошибку "не верные логин\пароль".

error.log
Код:
radius 09-05/12:31:43 ERROR [rdsLstnr-p-4-t-2] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
radius 09-05/12:31:42 ERROR [rdsLstnr-p-4-t-3] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)


radius.log
Код:
09-05/07:52:48  INFO [main] DefaultServerSetup - Binding javax.jms.ConnectionFactory[org.apache.activemq.ActiveMQConnectionFactory@96bf47] to java:comp/env/mq/connectionFactory
09-05/07:52:48  INFO [main] DefaultServerSetup - Init DB connection pools
09-05/07:52:49  INFO [main] DefaultServerSetup - Binding JDBC pool "master" to java:comp/env/jdbc/master
09-05/07:52:52  INFO [main] DefaultServerSetup - Init trash pools..
09-05/07:52:58  INFO [main] DefaultServerSetup - Init trash pools..
09-05/07:53:14  INFO [main] Radius - Starting radius auth_port:1812  acct_port:1813 admin_port:1955
09-05/07:53:17  INFO [main] Radius - Init processor
        class: ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor
        mid: 2
09-05/07:53:17  INFO [main] radius - Eap not enabled (keystore file not loaded).
09-05/07:53:21  INFO [main] Radius - Starting authentication listener...
09-05/07:53:21  INFO [main] DatagramChannelListener - Open socket [0.0.0.0/0.0.0.0:1812]
09-05/07:53:21  INFO [main] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.RadiusListener socket init ok.
09-05/07:53:21  INFO [main] Radius - Starting accounting listener...
09-05/07:53:21  INFO [main] DatagramChannelListener - Open socket [0.0.0.0/0.0.0.0:1813]
09-05/07:53:21  INFO [main] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.RadiusListener socket init ok.
09-05/07:53:21  INFO [Thread-22] AdminPortListener - Starting AdminPortListener on 1955
09-05/12:25:29  INFO [rdsLstnr-p-5-t-1] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 1
Authenticator: {71 92 96 90 D7 E6 15 38 7D 6C 1D 4A 8F 7A 41 89}
Attributes:
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  Acct-Status-Type=7
  Acct-Delay-Time=0

09-05/12:25:29  INFO [rdsLstnr-p-5-t-1] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 1
Authenticator: {5D AF E9 9D 26 51 8F 60 C1 6A 6D 7D 6A E5 24 29}
Attributes:
69

09-05/12:25:31  INFO [rdsLstnr-p-5-t-2] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 2
Authenticator: {99 A2 DA 18 1A 25 62 96 88 F4 00 54 43 34 0A 43}
Attributes:
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  Acct-Status-Type=7
  Acct-Delay-Time=0

09-05/12:25:31  INFO [rdsLstnr-p-5-t-2] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 2
Authenticator: {16 86 1F 00 E5 1A 06 2B C6 12 EC FF CD 04 40 36}
Attributes:
15

09-05/12:31:41  INFO [rdsLstnr-p-4-t-1] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 3
Authenticator: {6B 8B 45 67 32 7B 23 C6 64 3C 98 69 66 33 48 73}
Attributes:
  User-Name=28350
  NAS-Identifier=MikroTik
  User-Password=5131136665
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2138046464
  Service-Type=1
  Framed-IP-Address=10.0.0.243
  Acct-Session-Id=80900000
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.243
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/12:31:42  INFO [rdsLstnr-p-4-t-2] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 3
Authenticator: {6B 8B 45 67 32 7B 23 C6 64 3C 98 69 66 33 48 73}
Attributes:
  User-Name=28350
  NAS-Identifier=MikroTik
  User-Password=5131136665
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2138046464
  Service-Type=1
  Framed-IP-Address=10.0.0.243
  Acct-Session-Id=80900000
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.243
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/12:31:42  INFO [rdsLstnr-p-4-t-1] CommonKernelEventProcessor - Process event cid:0; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 0; scid: -1; userId: 0; timestamp: 1346873502339
09-05/12:31:42  INFO [rdsLstnr-p-4-t-1] CommonKernelEventProcessor - Process event cid:98; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 98; scid: -1; userId: 0; timestamp: 1346873502493
09-05/12:31:42  INFO [rdsLstnr-p-4-t-3] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 3
Authenticator: {6B 8B 45 67 32 7B 23 C6 64 3C 98 69 66 33 48 73}
Attributes:
  User-Name=28350
  NAS-Identifier=MikroTik
  User-Password=5131136665
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2138046464
  Service-Type=1
  Framed-IP-Address=10.0.0.243
  Acct-Session-Id=80900000
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.243
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/12:31:42  INFO [rdsLstnr-p-4-t-3] RadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 3
Authenticator: {03 3B 0D 33 4F 9C 87 0E 3A B6 BE 23 A2 A1 CE 48}
Attributes:

Process time auth: 406

09-05/12:31:42  INFO [rdsLstnr-p-4-t-2] RadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 3
Authenticator: {03 3B 0D 33 4F 9C 87 0E 3A B6 BE 23 A2 A1 CE 48}
Attributes:
Process time auth: 716

09-05/12:31:43 ERROR [rdsLstnr-p-4-t-2] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
09-05/12:31:42 ERROR [rdsLstnr-p-4-t-3] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        at java.lang.Thread.run(Thread.java:722)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
09-05/12:31:43  INFO [rdsLstnr-p-4-t-1] RadiusListenerWorker - RESPONSE:
Packet type: Access-Accept
Identifier: 3
Authenticator: {67 74 FC 5A 5F 8E F8 B2 47 AC 09 46 56 21 5C D8}
Attributes:
  Acct-Interim-Interval=60
  Service-Type=2
  Framed-Protocol=1
  Session-Timeout=900
  Mikrotik-Rate-Limit=1538k

Process time auth: 1172

09-05/12:31:50  INFO [rdsLstnr-p-4-t-4] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 4
Authenticator: {74 B0 DC 51 19 49 5C FF 2A E8 94 4A 62 55 58 EC}
Attributes:
  User-Name=28350
  NAS-Identifier=MikroTik
  User-Password=5131136665
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2138046463
  Service-Type=1
  Framed-IP-Address=10.0.0.243
  Acct-Session-Id=80900001
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.243
  WISPr-Logoff-URL=http://10.0.0.1/logout


mq.log
Код:
09-05/07:52:52  INFO [EventProcessor-init] EventProcessor - Init EventProcessor MQ connection factory...
09-05/12:31:43  INFO [event-proc-p-2-t-1] ContractRuntimeMap - Taked event: Event[ru.bitel.bgbilling.kernel.event.events.ContractStatusModifiedEvent] moduleId: 0; pluginId: no; cid: 98; scid: -1; userId: 0; timestamp: 1346873502448


script.log
Код:
09-05/07:53:15  INFO [main] ScriptEventListener - Starting ScriptEventListener...
09-05/07:53:15  INFO [main] ScriptEventListener - Relinking script functions.
09-05/07:53:15  INFO [main] ScriptEventListener - Skip event type bitel.billing.server.script.bean.event.ContractWebLoginEvent. Class not found for this application.
09-05/07:53:15  INFO [main] ScriptEventListener - Skip event type ru.bitel.bgbilling.modules.npay.server.bean.event.DebetStatusManageOpenGetAdditionalCharge. Class not found for this application.
09-05/07:53:15  INFO [main] ScriptEventListener - Skip event type ru.bitel.bgbilling.modules.npay.server.bean.event.ContractNpayChangedEvent. Class not found for this application.
09-05/07:53:15  INFO [main] ScriptEventListener - Skip event type ru.bitel.bgbilling.modules.npay.server.bean.event.DebetStatusManageAfterOpen. Class not found for this application.
09-05/07:53:15  INFO [main] ScriptEventListener - Skip event type ru.bitel.bgbilling.plugins.documents.server.bean.event.GenerateDocumentEvent. Class not found for this application.
09-05/07:53:16  INFO [main] ScriptEventListener - Starting DynamicScriptEventListener...


processor.log
Код:
09-05/12:48:26  INFO [main] RadiusDictionary - Load RADIUS dictionary
09-05/12:48:28  INFO [main] RadiusProcessor - Reloading nas list
09-05/12:48:28  INFO [main] NasList - Loading NAS list...
09-05/12:48:28  INFO [main] PodNasConnectionInspector - logCoa=true
09-05/12:48:28  INFO [main] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.inspectors.PodNasConnectionInspector$1 socket init ok.
09-05/12:48:29  INFO [main] processor - Starting wait remover timeout=120 MT-NAS-1
09-05/12:48:29  INFO [Thread-12] processor - Starting WaitRemover for Nas id: MT-NAS-1; ip: 192.168.88.1
09-05/12:48:29  INFO [main] processor - Starting connections month breaker MT-NAS-1
09-05/12:48:29  INFO [Thread-14] TariffOptionWatcher - Starting TariffOptionWatcher for Nas id: MT-NAS-1; ip: 192.168.88.1
09-05/12:48:29  INFO [main] NasList - LOADED NAS: Nas id: MT-NAS-1; ip: 192.168.88.1
CONFIG:
callback.support=1
card.activate.service=0
coa.log=1
dialup.workmode=1
month.break=1
month.break.period=3600
nas.inspector.class=ru.bitel.bgbilling.kernel.network.radius.inspectors.PodNasConnectionInspector
nas.inspector.coa.retries=2
nas.inspector.coa.send.all.attributes=1
nas.inspector.coa.threads=4
nas.inspector.coa.timeout=5
nas.inspector.kill.max_messages=5
nas.inspector.radius.attributes=User-Name;Framed-IP-Address;Acct-Session-Id;Mikrotik-Advertise-URL
nas.inspector.radius.port=1700
nas.inspector.sleep_time=60
nas.port_time.default.*=4
nas.port_traffic.default.*=

09-05/12:48:29  INFO [main] DetailCompressRules - Session detail compress rules:
09-05/12:48:29  INFO [main] processor - Dynamic DNS init => false
09-05/12:48:30  INFO [main] DialUpRadiusProcessor - Restored 0/0 connections (100.00%)
09-05/12:48:30  INFO [main] DialUpRadiusProcessor - Restored 0/0 connections (100.00%)
09-05/12:48:30  INFO [main] processor - Connection count checker..
09-05/12:48:30  INFO [main] processor - UPDATE mode SLEEP setter, timeout=120
09-05/12:48:31  INFO [main] StaticAddressMonitor - Reload static addresses..
09-05/12:48:46  INFO [Thread-13] processor - Starting ConnectionBreaker for: Nas id: MT-NAS-1; ip: 192.168.88.1
Автор:  [S] [ 05 сен 2012, 18:13 ]
Заголовок сообщения:  Re: [5.2] Проблема при авторизации
Со стороны Микротика происходит примерно следующее:

Код:
08:09:40 hotspot,info,debug 22195 (10.0.0.242): trying to log in by http-pap
08:09:40 hotspot,debug 22195 (10.0.0.242): local user not found
08:09:40 hotspot,debug 22195 (10.0.0.242): sending RADIUS authentication request
08:09:40 hotspot,debug 22195 (10.0.0.242): Access-Reject from RADIUS
08:09:42 hotspot,info,debug 22195 (10.0.0.242): login failed: invalid username or password
08:09:49 hotspot,info,debug 22195 (10.0.0.242): trying to log in by http-pap
08:09:49 hotspot,debug 22195 (10.0.0.242): local user not found
08:09:49 hotspot,debug 22195 (10.0.0.242): sending RADIUS authentication request
08:09:49 hotspot,debug 22195 (10.0.0.242): Access-Accept from RADIUS
08:09:49 hotspot,debug 22195 (10.0.0.242): using profile <default>
08:09:49 hotspot,debug 22195 (10.0.0.242): interim-update <60> from RADIUS
08:09:49 hotspot,debug 22195 (10.0.0.242): rate limit <1538k> from RADIUS
08:09:49 hotspot,debug 22195 (10.0.0.242): session timeout <900> from RADIUS
08:09:49 hotspot,debug 22195 (10.0.0.242): adding ip->user binding
08:09:49 hotspot,debug 22195 (10.0.0.242): adding queue <1538k>
08:09:49 hotspot,account,info,debug 22195 (10.0.0.242): logged in


4 и 5 строка, но в логах только то, что я писал выше, в мониторе биллинга - тишина.
Автор:  [S] [ 05 сен 2012, 21:50 ]
Заголовок сообщения:  Re: [5.2] Проблема при авторизации
Поставил версию Java HotSpot(TM) Client VM [1.6.0_35].
Попробовал, всё тоже самое. Полный лог.

radius.log

Код:
09-05/23:41:24  INFO [main] DefaultServerSetup - Binding javax.jms.ConnectionFactory[org.apache.activemq.ActiveMQConnectionFactory@120a47e] to java:comp/env/mq/connectionFactory
09-05/23:41:24  INFO [main] DefaultServerSetup - Init DB connection pools
09-05/23:41:25  INFO [main] DefaultServerSetup - Binding JDBC pool "master" to java:comp/env/jdbc/master
09-05/23:41:26  INFO [main] DefaultServerSetup - Init trash pools..
09-05/23:41:30  INFO [main] DefaultServerSetup - Init trash pools..
09-05/23:41:41  INFO [main] Radius - Starting radius auth_port:1812  acct_port:1813 admin_port:1955
09-05/23:41:42  INFO [main] Radius - Init processor
        class: ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor
        mid: 2
09-05/23:41:42  INFO [main] radius - Eap not enabled (keystore file not loaded).
09-05/23:41:45  INFO [main] Radius - Starting authentication listener...
09-05/23:41:45  INFO [main] Setup - Load config for mid=2
09-05/23:41:45  INFO [main] DatagramChannelListener - Open socket [0.0.0.0/0.0.0.0:1812]
09-05/23:41:45  INFO [main] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.RadiusListener socket init ok.
09-05/23:41:45  INFO [main] Radius - Starting accounting listener...
09-05/23:41:45  INFO [main] DatagramChannelListener - Open socket [0.0.0.0/0.0.0.0:1813]
09-05/23:41:45  INFO [main] DatagramChannelListener - ru.bitel.bgbilling.kernel.network.radius.RadiusListener socket init ok.
09-05/23:41:45  INFO [Thread-21] AdminPortListener - Starting AdminPortListener on 1955
09-05/23:42:14  INFO [rdsLstnr-p-4-t-1] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 1
Authenticator: {71 92 96 90 D7 E6 15 38 7D 6C 1D 4A 8F 7A 41 89}
Attributes:
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  Acct-Status-Type=7
  Acct-Delay-Time=0

09-05/23:42:14  INFO [rdsLstnr-p-4-t-1] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 1
Authenticator: {5D AF E9 9D 26 51 8F 60 C1 6A 6D 7D 6A E5 24 29}
Attributes:
29

09-05/23:42:16  INFO [rdsLstnr-p-4-t-2] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 2
Authenticator: {99 A2 DA 18 1A 25 62 96 88 F4 00 54 43 34 0A 43}
Attributes:
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  Acct-Status-Type=7
  Acct-Delay-Time=0

09-05/23:42:16  INFO [rdsLstnr-p-4-t-2] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 2
Authenticator: {16 86 1F 00 E5 1A 06 2B C6 12 EC FF CD 04 40 36}
Attributes:
13

09-05/23:44:02  INFO [rdsLstnr-p-3-t-1] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 3
Authenticator: {6B 8B 45 67 32 7B 23 C6 64 3C 98 69 66 33 48 73}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  User-Password=6828784983
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900736
  Service-Type=1
  Framed-IP-Address=10.0.0.241
  Acct-Session-Id=80c00000
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/23:44:02  INFO [rdsLstnr-p-3-t-2] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 3
Authenticator: {6B 8B 45 67 32 7B 23 C6 64 3C 98 69 66 33 48 73}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  User-Password=6828784983
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900736
  Service-Type=1
  Framed-IP-Address=10.0.0.241
  Acct-Session-Id=80c00000
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/23:44:03  INFO [rdsLstnr-p-3-t-1] CommonKernelEventProcessor - Process event cid:0; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 0; scid: -1; userId: 0; timestamp: 1346913843009
09-05/23:44:03  INFO [rdsLstnr-p-3-t-1] CommonKernelEventProcessor - Process event cid:115; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 115; scid: -1; userId: 0; timestamp: 1346913843178
09-05/23:44:03  INFO [rdsLstnr-p-3-t-3] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 3
Authenticator: {6B 8B 45 67 32 7B 23 C6 64 3C 98 69 66 33 48 73}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  User-Password=6828784983
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900736
  Service-Type=1
  Framed-IP-Address=10.0.0.241
  Acct-Session-Id=80c00000
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/23:44:03  INFO [rdsLstnr-p-3-t-3] RadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 3
Authenticator: {03 3B 0D 33 4F 9C 87 0E 3A B6 BE 23 A2 A1 CE 48}
Attributes:

Process time auth: 402

09-05/23:44:03 ERROR [rdsLstnr-p-3-t-3] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
09-05/23:44:03  INFO [rdsLstnr-p-3-t-2] RadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 3
Authenticator: {03 3B 0D 33 4F 9C 87 0E 3A B6 BE 23 A2 A1 CE 48}
Attributes:

Process time auth: 735

09-05/23:44:03 ERROR [rdsLstnr-p-3-t-2] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
09-05/23:44:04  INFO [rdsLstnr-p-3-t-1] RadiusListenerWorker - RESPONSE:
Packet type: Access-Accept
Identifier: 3
Authenticator: {92 53 E7 21 93 00 D2 9F CE 4A F8 20 04 4D CC 91}
Attributes:
  Acct-Interim-Interval=60
  Service-Type=2
  Framed-Protocol=1
  Session-Timeout=600
  Mikrotik-Rate-Limit=1024k

Process time auth: 1408

09-05/23:44:08  INFO [rdsLstnr-p-3-t-4] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 4
Authenticator: {74 B0 DC 51 19 49 5C FF 2A E8 94 4A 62 55 58 EC}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  User-Password=6828784983
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900735
  Service-Type=1
  Framed-IP-Address=10.0.0.241
  Acct-Session-Id=80c00001
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/23:44:08  INFO [rdsLstnr-p-3-t-4] RadiusListenerWorker - RESPONSE:
Packet type: Access-Accept
Identifier: 4
Authenticator: {8A 67 ED 08 E2 77 DE E1 2F D4 29 5B 31 FE CA 7F}
Attributes:
  Acct-Interim-Interval=60
  Service-Type=2
  Framed-Protocol=1
  Session-Timeout=600
  Mikrotik-Rate-Limit=1024k

Process time auth: 284

09-05/23:44:08  INFO [rdsLstnr-p-4-t-3] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 5
Authenticator: {74 0E A0 A3 4A E6 FE 45 08 D0 51 34 6A 5B 7A BB}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900735
  Framed-IP-Address=10.0.0.241
  Acct-Status-Type=1
  Acct-Delay-Time=0
  Acct-Session-Id=80c00001
  NAS-Port-Id=ether3
  Event-Timestamp=86521
  NAS-Port-Type=19
  Calling-Station-Id=48-5D-60-AF-1B-CE
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241

09-05/23:44:08  INFO [rdsLstnr-p-4-t-3] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 5
Authenticator: {84 41 4B 65 3C A4 A4 EE 54 EA A4 A7 08 4B 28 8B}
Attributes:

Process time start: 176

09-05/23:45:08  INFO [rdsLstnr-p-4-t-4] update - REQUEST:
Packet type: Accounting-Request
Identifier: 6
Authenticator: {4C D5 7F F0 0E 91 52 A4 4B 58 45 4B 36 B3 99 D9}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900735
  Framed-IP-Address=10.0.0.241
  Acct-Input-Octets=7784
  Acct-Output-Octets=12652
  Acct-Status-Type=3
  Acct-Delay-Time=0
  Acct-Session-Time=59
  Acct-Input-Packets=71
  Acct-Session-Id=80c00001
  NAS-Port-Id=ether3
  Acct-Output-Packets=52
  Event-Timestamp=86581
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=19
  Calling-Station-Id=48-5D-60-AF-1B-CE
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241

09-05/23:45:08  INFO [rdsLstnr-p-4-t-4] update - RESPONSE:
Packet type: Accounting-Response
Identifier: 6
Authenticator: {10 AC 83 16 EC 9E 0D D5 E4 5D 71 55 CC AD E1 43}
Attributes:

Process time update: 170

09-05/23:45:33  INFO [rdsLstnr-p-4-t-5] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 7
Authenticator: {95 DF 2E 83 1C D3 BF 52 A5 C2 E7 7D FD 65 6D 28}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900735
  Framed-IP-Address=10.0.0.241
  Acct-Input-Octets=8761
  Acct-Output-Octets=12992
  Acct-Status-Type=2
  Acct-Delay-Time=0
  Acct-Session-Time=84
  Acct-Input-Packets=84
Packet type: Accounting-Response
Identifier: 6
Authenticator: {10 AC 83 16 EC 9E 0D D5 E4 5D 71 55 CC AD E1 43}
Attributes:

Process time update: 170

09-05/23:45:33  INFO [rdsLstnr-p-4-t-5] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 7
Authenticator: {95 DF 2E 83 1C D3 BF 52 A5 C2 E7 7D FD 65 6D 28}
Attributes:
  User-Name=22319
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900735
  Framed-IP-Address=10.0.0.241
  Acct-Input-Octets=8761
  Acct-Output-Octets=12992
  Acct-Status-Type=2
  Acct-Delay-Time=0
  Acct-Session-Time=84
  Acct-Input-Packets=84
  Acct-Session-Id=80c00001
  Acct-Terminate-Cause=1
  NAS-Port-Id=ether3
  Acct-Output-Packets=59
  Event-Timestamp=86605
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=19
  Calling-Station-Id=48-5D-60-AF-1B-CE
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241

09-05/23:45:33  INFO [rdsLstnr-p-4-t-5] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 7
Authenticator: {A5 8F 0B 30 1D E6 48 EF D1 71 91 32 73 93 09 72}
Attributes:

Process time stop: 19


Причем, повторная, валидная, авторизация, выглядит вот так:

Код:
09-05/23:47:23  INFO [rdsLstnr-p-3-t-5] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 8
Authenticator: {23 8E 1F 29 46 E8 7C CD 3D 1B 58 BA 50 7E D7 AB}
Attributes:
  User-Name=30461
  NAS-Identifier=MikroTik
  User-Password=7753479722
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900734
  Service-Type=1
  Framed-IP-Address=10.0.0.241
  Acct-Session-Id=80c00002
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/23:47:23  INFO [rdsLstnr-p-3-t-5] CommonKernelEventProcessor - Process event cid:0; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 0; scid: -1; userId: 0; timestamp: 1346914043840
09-05/23:47:23  INFO [rdsLstnr-p-3-t-5] CommonKernelEventProcessor - Process event cid:116; event:Event[ru.bitel.bgbilling.kernel.event.events.system.ContractCreateEvent] moduleId: 0; pluginId: no; cid: 116; scid: -1; userId: 0; timestamp: 1346914043924
09-05/23:47:24  INFO [rdsLstnr-p-3-t-6] RadiusListenerWorker - REQUEST:
Packet type: Access-Request
Identifier: 8
Authenticator: {23 8E 1F 29 46 E8 7C CD 3D 1B 58 BA 50 7E D7 AB}
Attributes:
  User-Name=30461
  NAS-Identifier=MikroTik
  User-Password=7753479722
  NAS-Port-Id=ether3
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900734
  Service-Type=1
  Framed-IP-Address=10.0.0.241
  Acct-Session-Id=80c00002
  Calling-Station-Id=48-5D-60-AF-1B-CE
  NAS-Port-Type=19
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241
  WISPr-Logoff-URL=http://10.0.0.1/logout

09-05/23:47:24  INFO [rdsLstnr-p-3-t-5] RadiusListenerWorker - RESPONSE:
Packet type: Access-Accept
Identifier: 8
Authenticator: {21 A4 B1 53 AC 57 E5 D0 4C 57 88 4D 34 05 DA 84}
Attributes:
  Acct-Interim-Interval=60
  Service-Type=2
  Framed-Protocol=1
  Session-Timeout=600
  Mikrotik-Rate-Limit=1024k

Process time auth: 409

09-05/23:47:24  INFO [rdsLstnr-p-4-t-6] RadiusListenerWorker - REQUEST:
Packet type: Accounting-Request
Identifier: 9
Authenticator: {1A E0 21 48 9C C6 70 47 78 76 2D A0 A6 75 75 EC}
Attributes:
  User-Name=30461
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900734
  Framed-IP-Address=10.0.0.241
  Acct-Status-Type=1
  Acct-Delay-Time=0
  Acct-Session-Id=80c00002
  NAS-Port-Id=ether3
  Event-Timestamp=86716
  NAS-Port-Type=19
  Calling-Station-Id=48-5D-60-AF-1B-CE
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241

09-05/23:47:24  INFO [rdsLstnr-p-3-t-6] RadiusListenerWorker - RESPONSE:
Packet type: Access-Reject
Identifier: 8
Authenticator: {28 4C D6 AC A2 83 D5 DA 80 BD 62 9B 25 48 61 04}
Attributes:

Process time auth: 119

09-05/23:47:24 ERROR [rdsLstnr-p-3-t-6] RadiusListenerWorker -
java.lang.NullPointerException
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authenticationImpl(AbstractRadiusProcessor.java:352)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:591)
        at ru.bitel.bgbilling.modules.dialup.radius.DialUpRadiusProcessor.authenticationImpl(DialUpRadiusProcessor.java:1)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.authentication(AbstractRadiusProcessor.java:207)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:374)
        at ru.bitel.bgbilling.kernel.network.radius.AbstractRadiusProcessor.accessRequestImpl(AbstractRadiusProcessor.java:182)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:361)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.accessRequest(RadiusListenerWorker.java:333)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:213)
        at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
        at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
09-05/23:47:24  INFO [rdsLstnr-p-4-t-6] RadiusListenerWorker - RESPONSE:
Packet type: Accounting-Response
Identifier: 9
Authenticator: {1A 04 01 E7 DC 0E 89 64 C5 46 C5 66 5A 08 89 0C}
Attributes:

Process time start: 168

09-05/23:48:24  INFO [rdsLstnr-p-4-t-7] update - REQUEST:
Packet type: Accounting-Request
Identifier: 10
Authenticator: {60 0B F7 DC ED C7 5B 9F D1 62 72 CB 3D 26 B5 CE}
Attributes:
  User-Name=30461
  NAS-Identifier=MikroTik
  NAS-IP-Address=192.168.88.1
  NAS-Port=-2134900734
  Framed-IP-Address=10.0.0.241
  Acct-Input-Octets=5974
  Acct-Output-Octets=9989
  Acct-Status-Type=3
  Acct-Delay-Time=0
  Acct-Session-Time=60
  Acct-Input-Packets=45
  Acct-Session-Id=80c00002
  NAS-Port-Id=ether3
  Acct-Output-Packets=34
  Event-Timestamp=86777
  Acct-Output-Gigawords=0
  Acct-Input-Gigawords=0
  NAS-Port-Type=19
  Calling-Station-Id=48-5D-60-AF-1B-CE
  Called-Station-Id=hotspot1
  Mikrotik-Host-IP=10.0.0.241

09-05/23:48:24  INFO [rdsLstnr-p-4-t-7] update - RESPONSE:
Packet type: Accounting-Response
Identifier: 10
Authenticator: {0B EC 04 7B D0 5E FB 2D DE BE 63 6F B4 85 02 DB}
Attributes:

Process time update: 185
Автор:  snark [ 05 сен 2012, 22:21 ]
Заголовок сообщения:  Re: [5.2] Проблема при авторизации
Код:
NAS-Port=-2134900736

Отрицательный?
Автор:  [S] [ 06 сен 2012, 09:11 ]
Заголовок сообщения:  Re: [5.2] Проблема при авторизации
Эм...а где его поправить? И откуда он вообще берется, интерфейс ether3.
http://wiki.mikrotik.com/wiki/Manual:RADIUS_Client
Код:
NAS-Port - unique session ID

Я конфигурировал RADIUS через winbox, без каких-то дополнительных настроек. Посмотрю настройки через консоль, может быть там что-то настроено...

UPD: Вероятная проблема - не корректное время на NAS, попробую скорректировать и проверить.
Судя по форуму Микротика, это число, но не отрицательное, нормально для Микротика.
Автор:  [S] [ 06 сен 2012, 10:48 ]
Заголовок сообщения:  Re: [5.2] Проблема при авторизации
1. Поменял время на корректное, на величину Nas-Port и отрицательность данного значения не повлияло. Причем у Микторитка это значение положительное...
2. Включил debug на Микротик и увидел буквально следующее:

Код:
Jan/02/1970 07:03:34 web-proxy,debug
Jan/02/1970 07:04:36 hotspot,info,debug 29054 (10.0.0.241): trying to log in by http-pap
Jan/02/1970 07:04:36 hotspot,debug 29054 (10.0.0.241): local user not found
Jan/02/1970 07:04:36 hotspot,debug 29054 (10.0.0.241): sending RADIUS authentication request
Jan/02/1970 07:04:36 radius,debug new request 3f:2f code=Access-Request service=hotspot called-id=hotspot1
Jan/02/1970 07:04:36 radius,debug sending 3f:2f to 192.168.88.254:1812
Jan/02/1970 07:04:36 radius,debug,packet sending Access-Request with id 7 to 192.168.88.254:1812
Jan/02/1970 07:04:36 radius,debug,packet     Signature = 0x238e1f2946e87ccd3d1b58ba507ed7ab
Jan/02/1970 07:04:36 radius,debug,packet     NAS-Port-Type = 19
Jan/02/1970 07:04:36 radius,debug,packet     Calling-Station-Id = "48-5D-60-AF-1B-CE"
Jan/02/1970 07:04:36 radius,debug,packet     Called-Station-Id = "hotspot1"
Jan/02/1970 07:04:36 radius,debug,packet     NAS-Port-Id = "ether3"
Jan/02/1970 07:04:36 radius,debug,packet     User-Name = "29054"
Jan/02/1970 07:04:36 radius,debug,packet     NAS-Port = 2162163714
Jan/02/1970 07:04:36 radius,debug,packet     Acct-Session-Id = "80e00002"
Jan/02/1970 07:04:36 radius,debug,packet     Framed-IP-Address = 10.0.0.241
Jan/02/1970 07:04:36 radius,debug,packet     MT-Host-IP = 10.0.0.241
Jan/02/1970 07:04:36 radius,debug,packet     User-Password = 0x33383938393536313632
Jan/02/1970 07:04:36 radius,debug,packet     Service-Type = 1
Jan/02/1970 07:04:36 radius,debug,packet     WISPr-Logoff-URL = "http://10.0.0.1/logout"
Jan/02/1970 07:04:36 radius,debug,packet     NAS-Identifier = "MikroTik"
Jan/02/1970 07:04:36 radius,debug,packet     NAS-IP-Address = 192.168.88.1
Jan/02/1970 07:04:37 radius,debug resending 3f:2f
Jan/02/1970 07:04:37 radius,debug,packet sending Access-Request with id 7 to 192.168.88.254:1812
Jan/02/1970 07:04:37 radius,debug,packet     Signature = 0x238e1f2946e87ccd3d1b58ba507ed7ab
Jan/02/1970 07:04:37 radius,debug,packet     NAS-Port-Type = 19
Jan/02/1970 07:04:37 radius,debug,packet     Calling-Station-Id = "48-5D-60-AF-1B-CE"
Jan/02/1970 07:04:37 radius,debug,packet     Called-Station-Id = "hotspot1"
Jan/02/1970 07:04:37 radius,debug,packet     NAS-Port-Id = "ether3"
Jan/02/1970 07:04:37 radius,debug,packet     User-Name = "29054"
Jan/02/1970 07:04:37 radius,debug,packet     NAS-Port = 2162163714
Jan/02/1970 07:04:37 radius,debug,packet     Acct-Session-Id = "80e00002"
Jan/02/1970 07:04:37 radius,debug,packet     Framed-IP-Address = 10.0.0.241
Jan/02/1970 07:04:37 radius,debug,packet     MT-Host-IP = 10.0.0.241
Jan/02/1970 07:04:37 radius,debug,packet     User-Password = 0x33383938393536313632
Jan/02/1970 07:04:37 radius,debug,packet     Service-Type = 1
Jan/02/1970 07:04:37 radius,debug,packet     WISPr-Logoff-URL = "http://10.0.0.1/logout"
Jan/02/1970 07:04:37 radius,debug,packet     NAS-Identifier = "MikroTik"
Jan/02/1970 07:04:37 radius,debug,packet     NAS-IP-Address = 192.168.88.1
Jan/02/1970 07:04:37 hotspot,debug 29054 (10.0.0.241): Access-Reject from RADIUS
Jan/02/1970 07:04:37 radius,debug,packet received Access-Reject with id 7 from 192.168.88.254:1812
Jan/02/1970 07:04:37 radius,debug,packet     Signature = 0xb734d6e3529cb827f8f7381c8a8a0de2
Jan/02/1970 07:04:37 radius,debug received reply for 3f:2f
Jan/02/1970 07:04:38 hotspot,info,debug 29054 (10.0.0.241): login failed: invalid username or password
Jan/02/1970 07:04:40 hotspot,info,debug 29054 (10.0.0.241): trying to log in by http-pap
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): local user not found
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): sending RADIUS authentication request
Jan/02/1970 07:04:40 radius,debug new request 3f:30 code=Access-Request service=hotspot called-id=hotspot1
Jan/02/1970 07:04:40 radius,debug sending 3f:30 to 192.168.88.254:1812
Jan/02/1970 07:04:40 radius,debug,packet sending Access-Request with id 8 to 192.168.88.254:1812
Jan/02/1970 07:04:40 radius,debug,packet     Signature = 0x2eb141f241b71efb79e2a9e37545e146
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Port-Type = 19
Jan/02/1970 07:04:40 radius,debug,packet     Calling-Station-Id = "48-5D-60-AF-1B-CE"
Jan/02/1970 07:04:40 radius,debug,packet     Called-Station-Id = "hotspot1"
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Port-Id = "ether3"
Jan/02/1970 07:04:40 radius,debug,packet     User-Name = "29054"
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Port = 2162163715
Jan/02/1970 07:04:40 radius,debug,packet     Acct-Session-Id = "80e00003"
Jan/02/1970 07:04:40 radius,debug,packet     Framed-IP-Address = 10.0.0.241
Jan/02/1970 07:04:40 radius,debug,packet     MT-Host-IP = 10.0.0.241
Jan/02/1970 07:04:40 radius,debug,packet     User-Password = 0x33383938393536313632
Jan/02/1970 07:04:40 radius,debug,packet     Service-Type = 1
Jan/02/1970 07:04:40 radius,debug,packet     WISPr-Logoff-URL = "http://10.0.0.1/logout"
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Identifier = "MikroTik"
Jan/02/1970 07:04:40 radius,debug,packet     NAS-IP-Address = 192.168.88.1
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): Access-Accept from RADIUS
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): using profile <default>
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): interim-update <60> from RADIUS
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): rate limit <1024k> from RADIUS
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): session timeout <600> from RADIUS
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): adding ip->user binding
Jan/02/1970 07:04:40 radius,debug,packet received Access-Accept with id 8 from 192.168.88.254:1812
Jan/02/1970 07:04:40 radius,debug,packet     Signature = 0x52113dea10943baf49cf0d967f8a440b
Jan/02/1970 07:04:40 radius,debug,packet     Acct-Interim-Interval = 60
Jan/02/1970 07:04:40 radius,debug,packet     Service-Type = 2
Jan/02/1970 07:04:40 radius,debug,packet     Framed-Protocol = 1
Jan/02/1970 07:04:40 radius,debug,packet     Session-Timeout = 600
Jan/02/1970 07:04:40 radius,debug,packet     MT-Rate-Limit = "1024k"
Jan/02/1970 07:04:40 radius,debug received reply for 3f:30
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): adding queue <1024k>
Jan/02/1970 07:04:40 hotspot,account,info,debug 29054 (10.0.0.241): logged in
Jan/02/1970 07:04:40 hotspot,debug 29054 (10.0.0.241): sending RADIUS accounting Start request
Jan/02/1970 07:04:40 radius,debug new request 3f:33 code=Accounting-Request service=hotspot called-id=hotspot1
Jan/02/1970 07:04:40 radius,debug sending 3f:33 to 192.168.88.254:1813
Jan/02/1970 07:04:40 radius,debug,packet sending Accounting-Request with id 9 to 192.168.88.254:1813
Jan/02/1970 07:04:40 radius,debug,packet     Signature = 0xf0b83dd91cbefc07c77b3a94f2d02a52
Jan/02/1970 07:04:40 radius,debug,packet     Acct-Status-Type = 1
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Port-Type = 19
Jan/02/1970 07:04:40 radius,debug,packet     Calling-Station-Id = "48-5D-60-AF-1B-CE"
Jan/02/1970 07:04:40 radius,debug,packet     Called-Station-Id = "hotspot1"
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Port-Id = "ether3"
Jan/02/1970 07:04:40 radius,debug,packet     User-Name = "29054"
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Port = 2162163715
Jan/02/1970 07:04:40 radius,debug,packet     Acct-Session-Id = "80e00003"
Jan/02/1970 07:04:40 radius,debug,packet     Framed-IP-Address = 10.0.0.241
Jan/02/1970 07:04:40 radius,debug,packet     MT-Host-IP = 10.0.0.241
Jan/02/1970 07:04:40 radius,debug,packet     Event-Timestamp = 86680
Jan/02/1970 07:04:40 radius,debug,packet     NAS-Identifier = "MikroTik"
Jan/02/1970 07:04:40 radius,debug,packet     Acct-Delay-Time = 0


Вопрос возникает: а почему первый раз он отправляет два раза запрос с логин\паролем...

Схема простая:
1. Редирект на внешний URL POST-запросом
2. Внешний URL возвращает клиента на страницу login с POST-запросом, содержащим логин\пароль
3. Микротик идёт к радиусу и авторизовывает пользователя
4. Радиус попутно отправляет задание на создание договора на основании логина (карта)
Автор:  [S] [ 06 сен 2012, 11:39 ]
Заголовок сообщения:  Re: [5.2] Проблема при авторизации
Собственно, проблема решена.
Увеличил время в настройках RADIUS Микротика до 700ms. Микротик два раза отправлял запрос на авторизацию, радиус не понимал что с ним сделать и отбрасывал его.
Страница 1 из 1 Часовой пояс: UTC + 5 часов [ Летнее время ]
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/