[Serusers] ERROR: acc_rad_request: radius-ing failed

Rafael J. Risco G.V. rrisco at millicom.net.pe
Wed Jul 21 18:07:32 CEST 2004


Hi Jan
I did not see any other error in Ser or Radiusd Debuging, I´ve tested radiusclient with "radclient" and I think its working as I can see in the logs below:

sipser:/usr/local/etc/raddb# radclient -f digest localhost auth hola123
Received response ID 138, code 2, length = 45
        Reply-Message = "Hello, test with digest"

on the other hand, freeradius in debug mode just show me authentication process from Ser and it is doing "accounting" for other NAS like gnugk and cisco as5350 (please look the radius log below)...  About "radius-ing failed" message, I found this parameter in acc.c (line 674,2-16):

        if (rc_acct(SIP_PORT, send)!=OK_RC) {
                LOG(L_ERR, "ERROR: acc_rad_request: radius-ing failed\n");
                goto error;
        }
        rc_avpair_free(send);
        return 1;

please send some advice, 
thank you

Rafael

PS: FreeRadius is installed in the same host with ser (SuSE Linux 9.0)

Logs in radiusd -X:
###### from test tool "radclient":
rad_recv: Access-Request packet from host 127.0.0.1:1295, id=59, length=140
        User-Name = "test"
        Digest-Response = "631d6d73147add2f9e437f59bbc3aeb7"
        Digest-Attributes = "\001\013testrealm"
        Digest-Attributes = "\002\n1234abcd"
        Digest-Attributes = "\003\010INVITE"
        Digest-Attributes = "\004\034sip:5555551212 at example.com"
        Digest-Attributes = "\006\005MD5"
        Digest-Attributes = "\n\006test"
modcall: entering group authorize for request 95
  modcall[authorize]: module "preprocess" returns ok for request 95
  modcall[authorize]: module "chap" returns noop for request 95
  modcall[authorize]: module "eap" returns noop for request 95
    rlm_digest: Converting Digest-Attributes to something sane...
        Digest-Realm = "testrealm"
        Digest-Nonce = "1234abcd"
        Digest-Method = "INVITE"
        Digest-Uri = "sip:5555551212 at example.com"
        Digest-Algorithm = "MD5"
        Digest-User-Name = "test"
rlm_digest: Adding Auth-Type = DIGEST
  modcall[authorize]: module "digest" returns ok for request 95
    rlm_realm: No '@' in User-Name = "test", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[authorize]: module "suffix" returns noop for request 95
    users: Matched test at 309
  modcall[authorize]: module "files" returns ok for request 95
  modcall[authorize]: module "mschap" returns noop for request 95
modcall: group authorize returns ok for request 95
  rad_check_password:  Found Auth-Type Digest
auth: type "digest"
modcall: entering group authenticate for request 95
A1 = test:testrealm:test
A2 = INVITE:sip:5555551212 at example.com
H(A1) = 1e00d6dbd30441265df6064b9d9b7da9
H(A2) = 675b8c827b388805aa252ea38bfb6804
KD = 1e00d6dbd30441265df6064b9d9b7da9:1234abcd:675b8c827b388805aa252ea38bfb6804 
EXPECTED 631d6d73147add2f9e437f59bbc3aeb7
RECEIVED 631d6d73147add2f9e437f59bbc3aeb7
  modcall[authenticate]: module "digest" returns ok for request 95
modcall: group authenticate returns ok for request 95
radius_xlat:  'Hello, test with digest'
Sending Access-Accept of id 59 to 127.0.0.1:1295
        Reply-Message = "Hello, test with digest"
Finished request 95
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
--- Walking the entire request list ---
Cleaning up request 95 ID 59 with timestamp 40fe8d1c
Nothing to do.  Sleeping until we see a request.



##### :this is from endpoint registration:

Waking up in 6 seconds...
rad_recv: Access-Request packet from host 127.0.0.1:1295, id=41, length=209
        User-Name = "660300X at 200.110.2.132"
        Digest-Attributes = "\n\t660300X"
        Digest-Attributes = "\001\017200.110.2.132"
        Digest-Attributes = "\002*40fe8c883f9b07f4147001c9e11e49383af2cc20"
        Digest-Attributes = "\004\023sip:200.110.2.132"
        Digest-Attributes = "\003\nREGISTER"
        Digest-Response = "f5ceb840e2f11a0c4f83e39d2d61efeb"
        Service-Type = Sip-Session
        Sip-Uri-User = "6603000"
        NAS-IP-Address = 200.110.2.132
        NAS-Port = 5060
modcall: entering group authorize for request 75
  modcall[authorize]: module "preprocess" returns ok for request 75
  modcall[authorize]: module "chap" returns noop for request 75
  modcall[authorize]: module "eap" returns noop for request 75
    rlm_digest: Converting Digest-Attributes to something sane...
        Digest-User-Name = "660300X"
        Digest-Realm = "200.110.2.132"
        Digest-Nonce = "40fe8c883f9b07f4147001c9e11e49383af2cc20"
        Digest-Uri = "sip:200.110.2.132"
        Digest-Method = "REGISTER"
rlm_digest: Adding Auth-Type = DIGEST
  modcall[authorize]: module "digest" returns ok for request 75
    rlm_realm: Looking up realm "200.110.2.132" for User-Name = "660300X at 200.110.2.132"
    rlm_realm: No such realm "200.110.2.132"
  modcall[authorize]: module "suffix" returns noop for request 75
    users: Matched 660300X at 200.110.2.132 at 319
  modcall[authorize]: module "files" returns ok for request 75
  modcall[authorize]: module "mschap" returns noop for request 75
modcall: group authorize returns ok for request 75
  rad_check_password:  Found Auth-Type Digest
auth: type "digest"
modcall: entering group authenticate for request 75
A1 = 660300X:200.110.2.132:1234
A2 = REGISTER:sip:200.110.2.132
H(A1) = fa8f263b12c7457aeb25d91cdc6f0973
H(A2) = 84021d0e85c74628ca22606d4ef8ae80
KD = fa8f263b12c7457aeb25d91cdc6f0973:40fe8c883f9b07f4147001c9e11e49383af2cc20:84021d0e85c74628ca22606d4ef8ae80 
EXPECTED f5ceb840e2f11a0c4f83e39d2d61efeb
RECEIVED f5ceb840e2f11a0c4f83e39d2d61efeb
  modcall[authenticate]: module "digest" returns ok for request 75
modcall: group authenticate returns ok for request 75
radius_xlat:  'Welcome MILLICOM'
Sending Access-Accept of id 41 to 127.0.0.1:1295
        Reply-Message = "Welcome MILLICOM"
        Sip-Rpid = "6603000"
Finished request 75
Going to the next request






####### this is an acc log from other NAS :

rad_recv: Accounting-Request packet from host 200.110.2.131:10227, id=186, length=351
        Acct-Status-Type = Start
        NAS-IP-Address = 200.110.2.131
        NAS-Identifier = "GKProxy01"
        NAS-Port-Type = Virtual
        Service-Type = Login-User
        Acct-Session-Id = "1fc600b5"
        User-Name = "6603000"
        Framed-IP-Address = 200.110.2.130
        Calling-Station-Id = "6603000"
        Called-Station-Id = "1411#13054224049"
        h323-gw-id = "h323-gw-id=GKProxy01"
        h323-conf-id = "h323-conf-id=729F7600 A770D8E2 801C0002 A40055B2"
        h323-call-origin = "h323-call-origin=proxy"
        h323-call-type = "h323-call-type=VoIP"
        h323-setup-time = "h323-setup-time=10:47:03.000 PET Wed Jul 21 2004"
        h323-remote-address = "h323-remote-address=65.211.214.21"
        Acct-Delay-Time = 0
modcall: entering group preacct for request 136
  modcall[preacct]: module "preprocess" returns noop for request 136
    rlm_realm: No '@' in User-Name = "6603000", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[preacct]: module "suffix" returns noop for request 136
  modcall[preacct]: module "files" returns noop for request 136
modcall: group preacct returns noop for request 136
modcall: entering group accounting for request 136
rlm_acct_unique: WARNING: Attribute NAS-Port-Id was not found in request, unique ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = 200.110.2.131,NAS-IP-Address = 200.110.2.131,Acct-Session-Id = "1fc600b5",User-Name = "6603000"'
rlm_acct_unique: Acct-Unique-Session-ID = "299ec4b405cb6fb0".
  modcall[accounting]: module "acct_unique" returns ok for request 136
radius_xlat:  '/usr/local/var/log/radius/radacct/200.110.2.131/detail-20040721'
rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/200.110.2.131/detail-20040721
  modcall[accounting]: module "detail" returns ok for request 136
  modcall[accounting]: module "unix" returns noop for request 136
radius_xlat:  '/usr/local/var/log/radius/radutmp'
radius_xlat:  '6603000'
  rlm_radutmp: No NAS-Port seen.  Cannot do anything.
  rlm_radumtp: WARNING: checkrad will probably not work!
  modcall[accounting]: module "radutmp" returns noop for request 136
modcall: group accounting returns ok for request 136
Sending Accounting-Response of id 186 to 200.110.2.131:10227
Finished request 136
Going to the next request
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Accounting-Request packet from host 200.110.2.131:10227, id=187, length=508
        Acct-Status-Type = Stop
        NAS-IP-Address = 200.110.2.131
        NAS-Identifier = "GKProxy01"
        NAS-Port-Type = Virtual
        Service-Type = Login-User
        Acct-Session-Id = "1fc600b5"
        User-Name = "6603000"
        Framed-IP-Address = 200.110.2.130
        Acct-Session-Time = 1
        Calling-Station-Id = "6603000"
        Called-Station-Id = "1411#13054224049"
        h323-gw-id = "h323-gw-id=GKProxy01"
        h323-conf-id = "h323-conf-id=729F7600 A770D8E2 801C0002 A40055B2"
        h323-call-origin = "h323-call-origin=proxy"
        h323-call-type = "h323-call-type=VoIP"
        h323-setup-time = "h323-setup-time=10:47:03.000 PET Wed Jul 21 2004"
        h323-connect-time = "h323-connect-time=10:47:07.000 PET Wed Jul 21 2004"
        h323-disconnect-time = "h323-disconnect-time=10:47:08.000 PET Wed Jul 21 2004"
        h323-disconnect-cause = "h323-disconnect-cause=41"
        h323-remote-address = "h323-remote-address=65.211.214.21"
        Acct-Delay-Time = 0
modcall: entering group preacct for request 137
  modcall[preacct]: module "preprocess" returns noop for request 137
    rlm_realm: No '@' in User-Name = "6603000", looking up realm NULL
    rlm_realm: No such realm "NULL"
  modcall[preacct]: module "suffix" returns noop for request 137
  modcall[preacct]: module "files" returns noop for request 137
modcall: group preacct returns noop for request 137
modcall: entering group accounting for request 137
rlm_acct_unique: WARNING: Attribute NAS-Port-Id was not found in request, unique ID MAY be inconsistent
rlm_acct_unique: Hashing ',Client-IP-Address = 200.110.2.131,NAS-IP-Address = 200.110.2.131,Acct-Session-Id = "1fc600b5",User-Name = "6603000"'
rlm_acct_unique: Acct-Unique-Session-ID = "299ec4b405cb6fb0".
  modcall[accounting]: module "acct_unique" returns ok for request 137
radius_xlat:  '/usr/local/var/log/radius/radacct/200.110.2.131/detail-20040721'
rlm_detail: /usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/200.110.2.131/detail-20040721
  modcall[accounting]: module "detail" returns ok for request 137
  modcall[accounting]: module "unix" returns noop for request 137
radius_xlat:  '/usr/local/var/log/radius/radutmp'
radius_xlat:  '6603000'
  rlm_radutmp: No NAS-Port seen.  Cannot do anything.
  rlm_radumtp: WARNING: checkrad will probably not work!
  modcall[accounting]: module "radutmp" returns noop for request 137
modcall: group accounting returns ok for request 137
Sending Accounting-Response of id 187 to 200.110.2.131:10227
Finished request 137
Going to the next request
--- Walking the entire request list ---
Waking up in 1 seconds...
--- Walking the entire request list ---
Cleaning up request 136 ID 186 with timestamp 40fe8edd
Waking up in 5 seconds...
look the radius log below.--- Walking the entire request list ---
Cleaning up request 137 ID 187 with timestamp 40fe8ee2
Nothing to do.  Sleeping until we see a request.


Jan Janak <jan at iptel.org> escribió:

> There is some problem with the radiusclient library -- this error comes
> from the library. Do you see any other error message (generated by the
> radiusclient library or freeradius server) in the logs ?
> 
>   Jan.
> 
> On 20-07 11:18, Rafael J. Risco G.V. wrote:
> > Hi
> > 
> > please someone help me... I?m still having problems to obtain radius
> accounting and I found this error in the debug file:
> > 
> > .
> > .
> > 7(7511) ERROR: acc_rad_request: radius-ing failed
> >  7(7511) DEBUG: cleanup_uacs: RETR/FR timers reset
> >  7(7511) DEBUG: add_to_tail_of_timer[2]: 0x402f59b8
> >  7(7511) receive_msg: cleaning up
> >  5(7509) ERROR: acc_rad_request: radius-ing failed
> >  5(7509) SER: forwarding ACK  statelessly 
> >  5(7509) DEBUG: mk_proxy: doing DNS lookup...
> >  5(7509) check_via_address(200.110.6.58, 200.110.6.58, 0)
> >  5(7509) Sending:
> > ACK sip:6603000 at 10.0.0.236 SIP/2.0
> > Record-Route: <sip:6603000 at 200.110.2.132;ftag=4040fe43a4;lr=on>
> > Via: SIP/2.0/UDP 200.110.2.132;branch=0
> > Via: SIP/2.0/UDP 200.110.6.58:5060;branch=z9hG4bK4040fe43a418
> > From: <sip:6604000 at 200.110.2.132>;tag=4040fe43a4
> > To: <sip:6603000 at 200.110.2.132>;tag=8e006a06a4
> > Call-ID: 40d9ba40-16dd-fe9c-8043-0002a4005564 at 200.110.6.58
> > CSeq: 18 ACK
> > Route: <sip:6603000 at 200.110.2.132;ftag=4040fe43a4;lr=on>
> > Content-Length: 0
> > Max-Forwards: 69
> > 
> > .
> > .
> > this error appears only when I try "setflag(1)" for the transactions I
> want to account, also in this case the ACK message it comes too late
> (not when pick Up the phone...).
> > 
> > these are some details of my installation:
> > 
> > - SuSE Linux 9.0 (i586)
> > - ser-0.8.12
> > - I have followed "radius-how-to" very carefully.
> > - radiusclient-0.3.2
> > - freeradius-0.9.3  (installed in the same host with ser)
> > - I`m Not using mysql (do I have to use it??) 
> > - my current ser.cfg and endpoints configuration are shown below
> > 
> > thanks.
> > 
> > Rafael Risco
> > 
> > PS: Config Files:
> > 
> > #
> > # ----------- global configuration parameters
> ------------------------
> > 
> > # debug=3         # debug level (cmd line: -dddddddddd)
> > # fork=yes
> > # log_stderror=no        # (cmd line: -E)
> > 
> > #/* Uncomment these lines to enter debugging mode 
> > debug=6
> > fork=yes
> > log_stderror=yes
> > #*/
> > 
> > check_via=no    # (cmd. line: -v)
> > dns=no           # (cmd. line: -r)
> > rev_dns=no      # (cmd. line: -R)
> > port=5060
> > children=4
> > fifo="/tmp/ser_fifo"
> > 
> > # ------------------ module loading
> ----------------------------------
> > 
> > # Uncomment this if you want to use SQL database
> > #loadmodule "/usr/local/lib/ser/modules/mysql.so"
> > 
> > loadmodule "/usr/local/lib/ser/modules/sl.so"
> > loadmodule "/usr/local/lib/ser/modules/tm.so"
> > loadmodule "/usr/local/lib/ser/modules/rr.so"
> > loadmodule "/usr/local/lib/ser/modules/maxfwd.so"
> > loadmodule "/usr/local/lib/ser/modules/usrloc.so"
> > loadmodule "/usr/local/lib/ser/modules/registrar.so"
> > # loadmodule "/usr/local/lib/ser/modules/uri.so"
> > 
> > # Uncomment this if you want digest authentication
> > # mysql.so must be loaded !
> > loadmodule "/usr/local/lib/ser/modules/auth.so"
> > # loadmodule "/usr/local/lib/ser/modules/auth_db.so"
> > loadmodule "/usr/local/lib/ser/modules/auth_radius.so"
> > loadmodule "/usr/local/lib/ser/modules/group_radius.so"
> > loadmodule "/usr/local/lib/ser/modules/acc.so"
> > 
> > # load the NAT Helper Module
> > # loadmodule "/usr/local/lib/ser/modules/nathelper.so"
> > 
> > # ----------------- setting module-specific parameters
> ---------------
> > # -- usrloc params --
> > # modparam("usrloc", "db_mode",   0)
> > # Uncomment this if you want to use SQL database 
> > # for persistent storage and comment the previous line
> > # modparam("usrloc", "db_mode", 2)
> > # -- auth params --
> > # Uncomment if you are using auth module
> > #
> > # modparam("auth_db", "calculate_ha1", yes)
> > #
> > # If you set "calculate_ha1" parameter to yes (which true in this
> config), 
> > # uncomment also the following parameter)
> > #
> > # modparam("auth_db", "password_column", "password")
> > # -- rr params --
> > # add value to ;lr param to make some broken UAs happy
> > modparam("rr", "enable_full_lr", 1)
> > # modparam("acc","log_level",1)
> >
> modparam("auth_radius","radius_config","/usr/local/etc/radiusclient/radiusclient.conf")
> > modparam("auth_radius","service_type",15)
> >
> modparam("acc","radius_config","/usr/local/etc/radiusclient/radiusclient.conf")
> > modparam("acc", "service_type", 15)
> > modparam("acc", "radius_flag", 1)
> > modparam("acc", "radius_missed_flag", 3)
> > 
> > # -------------------------  request routing logic
> -------------------
> > 
> > # main routing logic
> > 
> > route{
> > 
> >         # initial sanity checks -- messages with
> >         # max_forwards==0, or excessively long requests
> >         if (!mf_process_maxfwd_header("10")) {
> >                 sl_send_reply("483","Too Many Hops");
> >                 break;
> >         };
> >         if ( msg:len > max_len ) {
> >                 sl_send_reply("513", "Message too big");
> >                 break;
> >         };
> > 
> >         # we record-route all messages -- to make sure that
> >         # subsequent messages will go through our proxy; that's
> >         # particularly good if upstream and downstream entities
> >         # use different transport protocol
> >         record_route();
> >         # loose-route processing
> > #        if (loose_route()) {
> > #                t_relay();
> > #                break;
> > #        };
> > 
> >         # if the request is for other domain use UsrLoc
> >         # (in case, it does not work, use the following command
> >         # with proper names and addresses in it)
> > 
> > 
> >                 if (method=="REGISTER") {
> > 
> >                         log(1, "REGISTER: Authenticating user\n");
> > 
> >                        if (!radius_www_authorize("")) {
> >                                 log(1, "REGISTER: challenging
> user\n");
> >                                 www_challenge("", "0");
> >                                 break;
> >                         };
> > 
> >                         save("location");
> >                         break;
> >                 };
> > 
> >         if (method=="INVITE") {
> > 
> >                 log(1, "INVITE\n");
> >                 setflag(1); /* set for accounting (the same value as
> in log_flag!) */
> >                 };
> > 
> > 
> >         if (method=="MESSAGE") {
> >                 log(1, "MESSAGE\n");
> >                 setflag(1); /* set for accounting (the same value as
> in log_flag!) */
> >                 };
> > 
> > 
> >         if (method=="BYE" || method=="CANCEL") {
> >                 log (1, "BYE or CANCEL\n");
> >                 setflag(1);
> >                 };
> > 
> > 
> >  
> >                # native SIP destinations are handled using our USRLOC
> DB
> >                 if (!lookup("location")) {
> >                         sl_send_reply("404", "Not Found");
> >                         break;
> >                 };
> > 
> > 
> >         # forward to current uri now; use stateful forwarding; that
> >         # works reliably even if we forward from TCP to UDP
> >         if (!t_relay()) {
> >                 sl_reply_error();
> >                 break;
> >         };
> > 
> > }
> > 
> > 




More information about the sr-users mailing list